[==========] 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:16:58.683382 32167 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.105.254:35831
I20260812 06:16:58.684438 32167 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:16:58.685071 32167 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:58.692230 32175 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:16:58.692240 32173 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:16:58.692274 32167 server_base.cc:1061] running on GCE node
W20260812 06:16:58.692296 32172 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:16:58.692999 32167 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:58.693141 32167 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:16:58.693197 32167 hybrid_clock.cc:648] HybridClock initialized: now 1786515418693195 us; error 0 us; skew 500 ppm
I20260812 06:16:58.695181 32167 webserver.cc:533] Webserver started at http://127.31.105.254:44067/ using document root <none> and password file <none>
I20260812 06:16:58.695765 32167 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:58.695824 32167 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:58.696071 32167 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:58.697773 32167 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/master-0-root/instance:
uuid: "87ec41cda4dd44cd8117636e17c3ea4e"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-wl2h"
I20260812 06:16:58.701464 32167 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.005s
I20260812 06:16:58.704056 32182 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:16:58.705451 32167 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:58.705618 32167 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/master-0-root
uuid: "87ec41cda4dd44cd8117636e17c3ea4e"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-wl2h"
I20260812 06:16:58.705730 32167 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-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:16:58.719103 32167 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:58.719776 32167 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:16:58.719961 32167 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:58.728070 32167 rpc_server.cc:307] RPC server started. Bound to: 127.31.105.254:35831
I20260812 06:16:58.728132 32247 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.105.254:35831 every 8 connection(s)
I20260812 06:16:58.730460 32248 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:16:58.736191 32248 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e: Bootstrap starting.
I20260812 06:16:58.738669 32248 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:58.739744 32248 log.cc:826] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:58.742169 32248 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e: No bootstrap required, opened a new log
I20260812 06:16:58.745190 32248 raft_consensus.cc:359] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87ec41cda4dd44cd8117636e17c3ea4e" member_type: VOTER }
I20260812 06:16:58.745373 32248 raft_consensus.cc:385] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:58.745467 32248 raft_consensus.cc:740] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 87ec41cda4dd44cd8117636e17c3ea4e, State: Initialized, Role: FOLLOWER
I20260812 06:16:58.746170 32248 consensus_queue.cc:260] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [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: "87ec41cda4dd44cd8117636e17c3ea4e" member_type: VOTER }
I20260812 06:16:58.746340 32248 raft_consensus.cc:399] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:58.746438 32248 raft_consensus.cc:493] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:58.746591 32248 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:58.747466 32248 raft_consensus.cc:515] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87ec41cda4dd44cd8117636e17c3ea4e" member_type: VOTER }
I20260812 06:16:58.747922 32248 leader_election.cc:304] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [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: 87ec41cda4dd44cd8117636e17c3ea4e; no voters: 
I20260812 06:16:58.748282 32248 leader_election.cc:290] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:58.748409 32252 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:58.748700 32252 raft_consensus.cc:697] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 1 LEADER]: Becoming Leader. State: Replica: 87ec41cda4dd44cd8117636e17c3ea4e, State: Running, Role: LEADER
I20260812 06:16:58.749164 32252 consensus_queue.cc:237] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [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: "87ec41cda4dd44cd8117636e17c3ea4e" member_type: VOTER }
I20260812 06:16:58.749382 32248 sys_catalog.cc:565] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:58.751250 32253 sys_catalog.cc:455] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "87ec41cda4dd44cd8117636e17c3ea4e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87ec41cda4dd44cd8117636e17c3ea4e" member_type: VOTER } }
I20260812 06:16:58.751362 32253 sys_catalog.cc:458] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:58.751212 32254 sys_catalog.cc:455] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 87ec41cda4dd44cd8117636e17c3ea4e. Latest consensus state: current_term: 1 leader_uuid: "87ec41cda4dd44cd8117636e17c3ea4e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87ec41cda4dd44cd8117636e17c3ea4e" member_type: VOTER } }
I20260812 06:16:58.751471 32254 sys_catalog.cc:458] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:58.751778 32271 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:58.751875 32167 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:58.754531 32271 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:58.760694 32271 catalog_manager.cc:1383] Generated new cluster ID: 4951fafb600b4d3c990a8adeaffaa913
I20260812 06:16:58.760797 32271 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:58.804391 32271 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:58.805420 32271 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:58.814469 32271 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e: Generated new TSK 0
I20260812 06:16:58.815284 32271 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:58.817014 32167 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:58.820556 32281 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:16:58.820616 32279 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:16:58.820637 32278 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:16:58.821105 32167 server_base.cc:1061] running on GCE node
I20260812 06:16:58.821332 32167 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:58.821393 32167 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:16:58.821419 32167 hybrid_clock.cc:648] HybridClock initialized: now 1786515418821419 us; error 0 us; skew 500 ppm
I20260812 06:16:58.822575 32167 webserver.cc:533] Webserver started at http://127.31.105.193:44153/ using document root <none> and password file <none>
I20260812 06:16:58.822774 32167 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:58.822839 32167 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:58.822926 32167 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:58.823457 32167 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/instance:
uuid: "a89534ec278241c7afffce0ceeba65d7"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-wl2h"
I20260812 06:16:58.825822 32167 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:58.827358 32287 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:16:58.827747 32167 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:58.827834 32167 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root
uuid: "a89534ec278241c7afffce0ceeba65d7"
format_stamp: "Formatted at 2026-08-12 06:16:58 on dist-test-slave-wl2h"
I20260812 06:16:58.827940 32167 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-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:16:58.833806 32167 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:58.834308 32167 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:58.834795 32167 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:58.835862 32167 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:58.835920 32167 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:58.836014 32167 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:58.836059 32167 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:58.843778 32167 rpc_server.cc:307] RPC server started. Bound to: 127.31.105.193:39147
I20260812 06:16:58.843804 32364 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.105.193:39147 every 8 connection(s)
I20260812 06:16:58.855584 32365 heartbeater.cc:344] Connected to a master server at 127.31.105.254:35831
I20260812 06:16:58.855842 32365 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:58.856374 32365 heartbeater.cc:507] Master 127.31.105.254:35831 requested a full tablet report, sending...
I20260812 06:16:58.857950 32200 ts_manager.cc:194] Registered new tserver with Master: a89534ec278241c7afffce0ceeba65d7 (127.31.105.193:39147)
I20260812 06:16:58.858175 32167 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013628519s
I20260812 06:16:58.859900 32200 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50428
I20260812 06:16:58.871500 32200 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50434:
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:16:58.886706 32323 tablet_service.cc:1511] Processing CreateTablet for tablet 6d70981dced640c7aa0428c345eb6ffc (DEFAULT_TABLE table=heavy-update-compaction-test [id=70faacd37cb040aa931bf20f5641debd]), partition=
I20260812 06:16:58.887285 32323 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6d70981dced640c7aa0428c345eb6ffc. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:58.889628 32381 tablet_bootstrap.cc:492] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Bootstrap starting.
I20260812 06:16:58.890800 32381 tablet_bootstrap.cc:654] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:58.892272 32381 tablet_bootstrap.cc:492] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: No bootstrap required, opened a new log
I20260812 06:16:58.892385 32381 ts_tablet_manager.cc:1403] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:58.892841 32381 raft_consensus.cc:359] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a89534ec278241c7afffce0ceeba65d7" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 39147 } }
I20260812 06:16:58.892971 32381 raft_consensus.cc:385] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:58.893005 32381 raft_consensus.cc:740] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a89534ec278241c7afffce0ceeba65d7, State: Initialized, Role: FOLLOWER
I20260812 06:16:58.893185 32381 consensus_queue.cc:260] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [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: "a89534ec278241c7afffce0ceeba65d7" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 39147 } }
I20260812 06:16:58.893291 32381 raft_consensus.cc:399] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:58.893329 32381 raft_consensus.cc:493] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:58.893378 32381 raft_consensus.cc:3060] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:58.894327 32381 raft_consensus.cc:515] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a89534ec278241c7afffce0ceeba65d7" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 39147 } }
I20260812 06:16:58.894477 32381 leader_election.cc:304] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [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: a89534ec278241c7afffce0ceeba65d7; no voters: 
I20260812 06:16:58.894687 32381 leader_election.cc:290] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:58.894872 32384 raft_consensus.cc:2804] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:58.895037 32381 ts_tablet_manager.cc:1434] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:58.895190 32384 raft_consensus.cc:697] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 1 LEADER]: Becoming Leader. State: Replica: a89534ec278241c7afffce0ceeba65d7, State: Running, Role: LEADER
I20260812 06:16:58.895332 32365 heartbeater.cc:499] Master 127.31.105.254:35831 was elected leader, sending a full tablet report...
I20260812 06:16:58.895547 32384 consensus_queue.cc:237] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [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: "a89534ec278241c7afffce0ceeba65d7" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 39147 } }
I20260812 06:16:58.899540 32200 catalog_manager.cc:5719] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 reported cstate change: term changed from 0 to 1, leader changed from <none> to a89534ec278241c7afffce0ceeba65d7 (127.31.105.193). New cstate: current_term: 1 leader_uuid: "a89534ec278241c7afffce0ceeba65d7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a89534ec278241c7afffce0ceeba65d7" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 39147 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:58.976292 32167 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.068s	user 0.023s	sys 0.007s
I20260812 06:16:59.096246 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushMRSOp(6d70981dced640c7aa0428c345eb6ffc): perf score=13.101815
I20260812 06:16:59.250715 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushMRSOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.154s	user 0.102s	sys 0.049s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":319,"delete_count":0,"dirs.queue_time_us":302,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":977,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34977,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":183,"threads_started":1,"update_count":1000}
I20260812 06:16:59.252259 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling LogGCOp(6d70981dced640c7aa0428c345eb6ffc): free 11976772 bytes of WAL
I20260812 06:16:59.252586 32294 log_reader.cc:385] T 6d70981dced640c7aa0428c345eb6ffc: removed 1 log segments from log reader
I20260812 06:16:59.252669 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000001 (ops 1-6)
I20260812 06:16:59.255971 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: LogGCOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:59.256453 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:16:59.274168 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.018s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7000,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.274758 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling UndoDeltaBlockGCOp(6d70981dced640c7aa0428c345eb6ffc): 12308958 bytes on disk
I20260812 06:16:59.275504 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: UndoDeltaBlockGCOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:16:59.276070 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:16:59.421270 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.145s	user 0.096s	sys 0.034s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528900,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":587,"lbm_read_time_us":10563,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22019,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":5650944,"thread_start_us":329,"threads_started":5,"update_count":1500}
I20260812 06:16:59.422243 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:16:59.476889 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.054s	user 0.013s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19123,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.477424 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:16:59.488618 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.011s	user 0.001s	sys 0.008s 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:16:59.489277 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:16:59.626343 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.137s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1047,"lbm_read_time_us":9012,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26767,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:16:59.626987 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:16:59.682968 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.056s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14405,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.683930 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:16:59.695259 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.695737 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:16:59.847204 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.151s	user 0.084s	sys 0.066s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1007,"lbm_read_time_us":10385,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23506,"lbm_writes_lt_1ms":443,"mutex_wait_us":413,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":49664,"update_count":2000}
I20260812 06:16:59.848501 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:16:59.896554 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.048s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18730,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.897083 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:16:59.909083 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4371,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.909817 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:00.054924 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.145s	user 0.113s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1570,"lbm_read_time_us":10350,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23460,"lbm_writes_lt_1ms":443,"mutex_wait_us":374,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:17:00.055907 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:00.107160 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.051s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18038,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.107676 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:00.120368 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4592,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.120877 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:00.242197 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.121s	user 0.091s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":125,"lbm_read_time_us":7630,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25030,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.242779 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:00.300858 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.058s	user 0.032s	sys 0.018s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19537,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":1500}
I20260812 06:17:00.301513 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:00.314178 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4456,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.314824 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:00.472339 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.157s	user 0.115s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":12663,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23726,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:00.473067 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:00.526623 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.053s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18383,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.527426 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:00.546165 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6537,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.546808 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:00.679658 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.133s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":730,"lbm_read_time_us":9075,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25772,"lbm_writes_lt_1ms":443,"mutex_wait_us":209,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:00.680366 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:00.732635 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.052s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19961,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.733230 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:00.747889 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4963,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.748426 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushMRSOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:00.790412 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushMRSOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.042s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1316414,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1524,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1747,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:00.791574 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=3.181125
I20260812 06:17:00.804018 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4270,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:00.804591 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling LogGCOp(6d70981dced640c7aa0428c345eb6ffc): free 129320492 bytes of WAL
I20260812 06:17:00.804874 32294 log_reader.cc:385] T 6d70981dced640c7aa0428c345eb6ffc: removed 13 log segments from log reader
I20260812 06:17:00.804934 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000002 (ops 7-11)
I20260812 06:17:00.804973 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000003 (ops 12-16)
I20260812 06:17:00.805009 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000004 (ops 17-21)
I20260812 06:17:00.805043 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000005 (ops 22-26)
I20260812 06:17:00.805078 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000006 (ops 27-31)
I20260812 06:17:00.805110 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000007 (ops 32-36)
I20260812 06:17:00.805140 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000008 (ops 37-40)
I20260812 06:17:00.805171 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000009 (ops 41-45)
I20260812 06:17:00.805204 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000010 (ops 46-50)
I20260812 06:17:00.805230 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000011 (ops 51-54)
I20260812 06:17:00.805262 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000012 (ops 55-59)
I20260812 06:17:00.805291 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000013 (ops 60-64)
I20260812 06:17:00.805320 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000014 (ops 65-69)
I20260812 06:17:00.837150 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: LogGCOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:00.837770 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling UndoDeltaBlockGCOp(6d70981dced640c7aa0428c345eb6ffc): 492 bytes on disk
I20260812 06:17:00.838413 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: UndoDeltaBlockGCOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.838973 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:00.863660 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.024s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5554,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.864228 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling LogGCOp(6d70981dced640c7aa0428c345eb6ffc): free 12017932 bytes of WAL
I20260812 06:17:00.864459 32294 log_reader.cc:385] T 6d70981dced640c7aa0428c345eb6ffc: removed 1 log segments from log reader
I20260812 06:17:00.864506 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000015 (ops 70-74)
I20260812 06:17:00.867041 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: LogGCOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:00.867467 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:00.881222 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.881716 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:01.108068 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.226s	user 0.149s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938894,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1145,"lbm_read_time_us":16091,"lbm_reads_lt_1ms":767,"lbm_write_time_us":45363,"lbm_writes_lt_1ms":743,"mutex_wait_us":375,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:17:01.108811 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=14.095187
I20260812 06:17:01.174444 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.065s	user 0.026s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25197,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.175230 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:01.186136 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.186620 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:01.385035 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.198s	user 0.137s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":15319,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32145,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:17:01.385701 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=11.118625
I20260812 06:17:01.431227 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.045s	user 0.033s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19238,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.432197 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:01.458307 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.026s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":5302,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:17:01.459304 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:01.470605 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:17:01.471241 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:01.669160 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.198s	user 0.127s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733838,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":961,"lbm_read_time_us":11803,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31754,"lbm_writes_lt_1ms":543,"mutex_wait_us":336,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:01.669757 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=11.118625
I20260812 06:17:01.705931 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.036s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16001,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.706734 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:01.725119 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.018s	user 0.012s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5881,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.725796 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:01.863770 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.138s	user 0.089s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":245,"lbm_read_time_us":8594,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26279,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2000}
I20260812 06:17:01.864703 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=11.118625
I20260812 06:17:01.902741 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.038s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14424,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.903429 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:01.916330 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4195,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.916931 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:02.055392 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.138s	user 0.109s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":984,"lbm_read_time_us":7795,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28169,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":441,"mutex_wait_us":526,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":298112,"update_count":2000}
I20260812 06:17:02.056308 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:02.111936 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.055s	user 0.019s	sys 0.028s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":22026,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.112535 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:02.123648 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.124217 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:02.262686 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.138s	user 0.102s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":697,"lbm_read_time_us":8912,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27955,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:17:02.263944 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:02.332818 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.069s	user 0.033s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20145,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.333516 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:02.345942 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4964,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.346468 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushMRSOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:02.383496 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushMRSOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.037s	user 0.030s	sys 0.002s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1832,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1596,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:02.384696 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling UndoDeltaBlockGCOp(6d70981dced640c7aa0428c345eb6ffc): 448 bytes on disk
I20260812 06:17:02.385275 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: UndoDeltaBlockGCOp(6d70981dced640c7aa0428c345eb6ffc) 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:17:02.385934 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:02.552707 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.166s	user 0.120s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1306,"lbm_read_time_us":10726,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27148,"lbm_writes_lt_1ms":443,"mutex_wait_us":350,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.553521 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling LogGCOp(6d70981dced640c7aa0428c345eb6ffc): free 112692378 bytes of WAL
I20260812 06:17:02.554080 32294 log_reader.cc:385] T 6d70981dced640c7aa0428c345eb6ffc: removed 11 log segments from log reader
I20260812 06:17:02.554205 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000016 (ops 75-79)
I20260812 06:17:02.554266 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000017 (ops 80-84)
I20260812 06:17:02.554313 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000018 (ops 85-89)
I20260812 06:17:02.554407 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000019 (ops 90-94)
I20260812 06:17:02.554456 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000020 (ops 95-99)
I20260812 06:17:02.554544 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000021 (ops 100-104)
I20260812 06:17:02.554595 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000022 (ops 105-109)
I20260812 06:17:02.554625 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000023 (ops 110-114)
I20260812 06:17:02.554661 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000024 (ops 115-119)
I20260812 06:17:02.554738 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000025 (ops 120-124)
I20260812 06:17:02.554786 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000026 (ops 125-129)
I20260812 06:17:02.587549 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: LogGCOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.034s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:17:02.588191 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=14.095187
I20260812 06:17:02.641937 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.053s	user 0.024s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24999,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.642517 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:02.655874 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.656713 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:02.831697 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.175s	user 0.147s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":162,"lbm_read_time_us":11514,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33499,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:17:02.832392 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=11.118625
I20260812 06:17:02.870419 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.038s	user 0.021s	sys 0.014s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15554,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:02.871096 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:02.899449 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.028s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5282,"lbm_writes_lt_1ms":93,"mutex_wait_us":3,"reinsert_count":0,"update_count":450}
I20260812 06:17:02.900015 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:02.911639 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.912112 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:03.081769 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.169s	user 0.125s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1278,"lbm_read_time_us":12999,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33369,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:03.082433 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:03.125998 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.043s	user 0.018s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21056,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.126911 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:03.144174 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.017s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.144774 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:03.283327 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.138s	user 0.106s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1496,"lbm_read_time_us":7873,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26282,"lbm_writes_lt_1ms":443,"mutex_wait_us":389,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.283885 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=14.095187
I20260812 06:17:03.347236 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.063s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23788,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.347836 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:03.361232 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4488,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.361974 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:03.540365 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.178s	user 0.142s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2587,"lbm_read_time_us":12925,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33824,"lbm_writes_lt_1ms":543,"mutex_wait_us":683,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:03.541276 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:03.583338 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.042s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19264,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.584133 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:03.602706 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.018s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.603286 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:03.770383 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.167s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":745,"lbm_read_time_us":10257,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29893,"lbm_writes_lt_1ms":443,"mutex_wait_us":109,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20608,"update_count":2000}
I20260812 06:17:03.771345 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:03.816641 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":19574,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.817391 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:03.840639 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.023s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.841218 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:04.039795 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.198s	user 0.140s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1253,"lbm_read_time_us":10850,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30368,"lbm_writes_lt_1ms":443,"mutex_wait_us":371,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.041731 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=11.118625
I20260812 06:17:04.092585 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.051s	user 0.034s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":23842,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:04.093130 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:04.115620 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.022s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.116328 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:04.127138 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3638,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.127810 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushMRSOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:04.173173 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushMRSOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.044s	user 0.041s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":571,"dirs.run_wall_time_us":2163,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1936,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:04.174155 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling LogGCOp(6d70981dced640c7aa0428c345eb6ffc): free 129320781 bytes of WAL
I20260812 06:17:04.174414 32294 log_reader.cc:385] T 6d70981dced640c7aa0428c345eb6ffc: removed 13 log segments from log reader
I20260812 06:17:04.174463 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000027 (ops 130-134)
I20260812 06:17:04.174492 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000028 (ops 135-138)
I20260812 06:17:04.174558 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000029 (ops 139-143)
I20260812 06:17:04.174609 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000030 (ops 144-148)
I20260812 06:17:04.174678 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000031 (ops 149-153)
I20260812 06:17:04.174731 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000032 (ops 154-158)
I20260812 06:17:04.174779 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000033 (ops 159-163)
I20260812 06:17:04.174845 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000034 (ops 164-168)
I20260812 06:17:04.174896 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000035 (ops 169-173)
I20260812 06:17:04.174919 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000036 (ops 174-178)
I20260812 06:17:04.174955 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000037 (ops 179-182)
I20260812 06:17:04.174980 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000038 (ops 183-187)
I20260812 06:17:04.175004 32294 log.cc:1079] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/6d70981dced640c7aa0428c345eb6ffc/wal-000000039 (ops 188-192)
I20260812 06:17:04.208841 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: LogGCOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.034s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:17:04.209384 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling UndoDeltaBlockGCOp(6d70981dced640c7aa0428c345eb6ffc): 492 bytes on disk
I20260812 06:17:04.209975 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: UndoDeltaBlockGCOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:17:04.210753 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=3.181125
I20260812 06:17:04.224260 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4970,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:04.225376 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=2.188937
I20260812 06:17:04.252015 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.026s	user 0.009s	sys 0.016s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5234,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.252933 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc): perf score=1.000000
I20260812 06:17:04.419756 32167 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.443s	user 1.989s	sys 0.143s
I20260812 06:17:04.498317 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: MajorDeltaCompactionOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.245s	user 0.159s	sys 0.084s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938886,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":18951,"lbm_reads_lt_1ms":771,"lbm_write_time_us":39940,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3500}
I20260812 06:17:04.498845 32366 maintenance_manager.cc:419] P a89534ec278241c7afffce0ceeba65d7: Scheduling FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc): perf score=10.126437
I20260812 06:17:04.529472 32167 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.109s	user 0.004s	sys 0.000s
I20260812 06:17:04.530408 32167 tablet_server.cc:179] TabletServer@127.31.105.193:0 shutting down...
I20260812 06:17:04.556352 32294 maintenance_manager.cc:643] P a89534ec278241c7afffce0ceeba65d7: FlushDeltaMemStoresOp(6d70981dced640c7aa0428c345eb6ffc) complete. Timing: real 0.057s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21195,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:04.557482 32167 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:04.558117 32167 tablet_replica.cc:333] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7: stopping tablet replica
I20260812 06:17:04.558414 32167 raft_consensus.cc:2243] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:04.558684 32167 raft_consensus.cc:2272] T 6d70981dced640c7aa0428c345eb6ffc P a89534ec278241c7afffce0ceeba65d7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:04.575925 32167 tablet_server.cc:196] TabletServer@127.31.105.193:0 shutdown complete.
I20260812 06:17:04.583304 32167 master.cc:562] Master@127.31.105.254:35831 shutting down...
I20260812 06:17:04.593235 32167 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:04.593607 32167 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:04.593755 32167 tablet_replica.cc:333] T 00000000000000000000000000000000 P 87ec41cda4dd44cd8117636e17c3ea4e: stopping tablet replica
I20260812 06:17:04.607895 32167 master.cc:584] Master@127.31.105.254:35831 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6029 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:04.729194 32167 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.105.254:45093
I20260812 06:17:04.729709 32167 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:04.733371 32404 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.733419 32167 server_base.cc:1061] running on GCE node
W20260812 06:17:04.733448 32405 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:04.733381 32411 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.733901 32167 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:04.733945 32167 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:04.733961 32167 hybrid_clock.cc:648] HybridClock initialized: now 1786515424733961 us; error 0 us; skew 500 ppm
I20260812 06:17:04.735857 32167 webserver.cc:533] Webserver started at http://127.31.105.254:41071/ using document root <none> and password file <none>
I20260812 06:17:04.736091 32167 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:04.736151 32167 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:04.736258 32167 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:04.736735 32167 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/master-0-root/instance:
uuid: "3177dc40aab54aeeaef38b33956e588a"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-wl2h"
I20260812 06:17:04.738517 32167 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:04.739964 32418 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.740437 32167 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:04.740552 32167 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/master-0-root
uuid: "3177dc40aab54aeeaef38b33956e588a"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-wl2h"
I20260812 06:17:04.740653 32167 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:04.749667 32167 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:04.750187 32167 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:04.755944 32167 rpc_server.cc:307] RPC server started. Bound to: 127.31.105.254:45093
I20260812 06:17:04.761111 32486 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:04.761483 32485 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.105.254:45093 every 8 connection(s)
I20260812 06:17:04.764139 32486 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a: Bootstrap starting.
I20260812 06:17:04.765138 32486 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:04.766710 32486 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a: No bootstrap required, opened a new log
I20260812 06:17:04.767482 32486 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3177dc40aab54aeeaef38b33956e588a" member_type: VOTER }
I20260812 06:17:04.767627 32486 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:04.767673 32486 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3177dc40aab54aeeaef38b33956e588a, State: Initialized, Role: FOLLOWER
I20260812 06:17:04.767884 32486 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [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: "3177dc40aab54aeeaef38b33956e588a" member_type: VOTER }
I20260812 06:17:04.768008 32486 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:04.768078 32486 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:04.768141 32486 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:04.796131 32486 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3177dc40aab54aeeaef38b33956e588a" member_type: VOTER }
I20260812 06:17:04.796402 32486 leader_election.cc:304] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [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: 3177dc40aab54aeeaef38b33956e588a; no voters: 
I20260812 06:17:04.796784 32486 leader_election.cc:290] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:04.797003 32489 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:04.797329 32489 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 1 LEADER]: Becoming Leader. State: Replica: 3177dc40aab54aeeaef38b33956e588a, State: Running, Role: LEADER
I20260812 06:17:04.797585 32486 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:04.797632 32489 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [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: "3177dc40aab54aeeaef38b33956e588a" member_type: VOTER }
I20260812 06:17:04.799008 32490 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3177dc40aab54aeeaef38b33956e588a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3177dc40aab54aeeaef38b33956e588a" member_type: VOTER } }
I20260812 06:17:04.799263 32490 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:04.799914 32167 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:04.799886 32491 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3177dc40aab54aeeaef38b33956e588a. Latest consensus state: current_term: 1 leader_uuid: "3177dc40aab54aeeaef38b33956e588a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3177dc40aab54aeeaef38b33956e588a" member_type: VOTER } }
I20260812 06:17:04.800055 32491 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:04.800118 32502 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:04.801995 32502 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:04.805518 32502 catalog_manager.cc:1383] Generated new cluster ID: 28dc42dbab664981a3c71d900a5cd7f6
I20260812 06:17:04.805621 32502 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:04.813717 32502 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:04.814422 32502 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:04.827490 32502 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a: Generated new TSK 0
I20260812 06:17:04.827991 32502 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:04.833597 32167 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:04.836669 32167 server_base.cc:1061] running on GCE node
W20260812 06:17:04.836670 32513 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:17:04.836669 32511 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:04.836974 32509 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:04.837497 32167 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:04.837579 32167 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:04.837598 32167 hybrid_clock.cc:648] HybridClock initialized: now 1786515424837599 us; error 0 us; skew 500 ppm
I20260812 06:17:04.838812 32167 webserver.cc:533] Webserver started at http://127.31.105.193:46481/ using document root <none> and password file <none>
I20260812 06:17:04.839077 32167 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:04.839143 32167 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:04.839236 32167 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:04.839730 32167 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/instance:
uuid: "b3fd01e1cf8d4735b6beaaad035cb44b"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-wl2h"
I20260812 06:17:04.842262 32167 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:17:04.844043 32518 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.844435 32167 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:04.844516 32167 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root
uuid: "b3fd01e1cf8d4735b6beaaad035cb44b"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-wl2h"
I20260812 06:17:04.844591 32167 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:04.872260 32167 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:04.873015 32167 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:04.873694 32167 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:04.874234 32167 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:04.874274 32167 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.874311 32167 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:04.874326 32167 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.878952 32167 rpc_server.cc:307] RPC server started. Bound to: 127.31.105.193:44593
I20260812 06:17:04.879114 32602 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.105.193:44593 every 8 connection(s)
I20260812 06:17:04.895042 32603 heartbeater.cc:344] Connected to a master server at 127.31.105.254:45093
I20260812 06:17:04.895232 32603 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:04.895516 32603 heartbeater.cc:507] Master 127.31.105.254:45093 requested a full tablet report, sending...
I20260812 06:17:04.896363 32431 ts_manager.cc:194] Registered new tserver with Master: b3fd01e1cf8d4735b6beaaad035cb44b (127.31.105.193:44593)
I20260812 06:17:04.897109 32167 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017153636s
I20260812 06:17:04.897563 32431 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33342
I20260812 06:17:04.906186 32431 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33354:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:04.917974 32554 tablet_service.cc:1511] Processing CreateTablet for tablet af1ecde8438143d5b0044a6c96d1b7ad (DEFAULT_TABLE table=heavy-update-compaction-test [id=8e9c037401524618bda92fa31ce39411]), partition=
I20260812 06:17:04.918380 32554 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet af1ecde8438143d5b0044a6c96d1b7ad. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:04.921337 32619 tablet_bootstrap.cc:492] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Bootstrap starting.
I20260812 06:17:04.922415 32619 tablet_bootstrap.cc:654] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:04.924082 32619 tablet_bootstrap.cc:492] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: No bootstrap required, opened a new log
I20260812 06:17:04.924218 32619 ts_tablet_manager.cc:1403] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:04.924687 32619 raft_consensus.cc:359] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3fd01e1cf8d4735b6beaaad035cb44b" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 44593 } }
I20260812 06:17:04.924827 32619 raft_consensus.cc:385] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:04.924904 32619 raft_consensus.cc:740] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b3fd01e1cf8d4735b6beaaad035cb44b, State: Initialized, Role: FOLLOWER
I20260812 06:17:04.925093 32619 consensus_queue.cc:260] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [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: "b3fd01e1cf8d4735b6beaaad035cb44b" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 44593 } }
I20260812 06:17:04.925216 32619 raft_consensus.cc:399] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:04.925268 32619 raft_consensus.cc:493] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:04.925326 32619 raft_consensus.cc:3060] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:05.007899 32619 raft_consensus.cc:515] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3fd01e1cf8d4735b6beaaad035cb44b" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 44593 } }
I20260812 06:17:05.008311 32619 leader_election.cc:304] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [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: b3fd01e1cf8d4735b6beaaad035cb44b; no voters: 
I20260812 06:17:05.008669 32619 leader_election.cc:290] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:05.008912 32621 raft_consensus.cc:2804] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:05.009166 32619 ts_tablet_manager.cc:1434] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Time spent starting tablet: real 0.085s	user 0.000s	sys 0.004s
I20260812 06:17:05.009202 32603 heartbeater.cc:499] Master 127.31.105.254:45093 was elected leader, sending a full tablet report...
I20260812 06:17:05.009220 32621 raft_consensus.cc:697] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 1 LEADER]: Becoming Leader. State: Replica: b3fd01e1cf8d4735b6beaaad035cb44b, State: Running, Role: LEADER
I20260812 06:17:05.009510 32621 consensus_queue.cc:237] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [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: "b3fd01e1cf8d4735b6beaaad035cb44b" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 44593 } }
I20260812 06:17:05.012918 32431 catalog_manager.cc:5719] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b reported cstate change: term changed from 0 to 1, leader changed from <none> to b3fd01e1cf8d4735b6beaaad035cb44b (127.31.105.193). New cstate: current_term: 1 leader_uuid: "b3fd01e1cf8d4735b6beaaad035cb44b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3fd01e1cf8d4735b6beaaad035cb44b" member_type: VOTER last_known_addr { host: "127.31.105.193" port: 44593 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:05.091795 32167 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.072s	user 0.016s	sys 0.012s
I20260812 06:17:05.132833 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushMRSOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=2.187753
I20260812 06:17:05.210763 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushMRSOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.078s	user 0.057s	sys 0.012s Metrics: {"bytes_written":5087239,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":35382,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":12453,"lbm_writes_lt_1ms":181,"peak_mem_usage":0,"reinsert_count":0,"rows_written":100,"update_count":620}
I20260812 06:17:05.211786 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=1.196750
I20260812 06:17:05.315285 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.103s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":3082,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:05.315901 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:05.423349 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.107s	user 0.017s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10866,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:05.424158 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling UndoDeltaBlockGCOp(af1ecde8438143d5b0044a6c96d1b7ad): 766 bytes on disk
I20260812 06:17:05.424747 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: UndoDeltaBlockGCOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":145,"lbm_reads_lt_1ms":4}
I20260812 06:17:05.425324 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:05.528859 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.103s	user 0.025s	sys 0.006s Metrics: {"bytes_written":8205080,"delete_count":0,"lbm_write_time_us":14860,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1000}
I20260812 06:17:05.529593 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:05.634828 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.105s	user 0.010s	sys 0.019s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13364,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":1000}
I20260812 06:17:05.635571 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:05.740772 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.105s	user 0.024s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13008,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:05.741743 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:05.853811 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.112s	user 0.013s	sys 0.015s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":11861,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:05.854681 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:05.950517 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.096s	user 0.012s	sys 0.010s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9872,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:05.951330 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:06.049018 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.097s	user 0.018s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11616,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:06.049949 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=5.165500
I20260812 06:17:06.150828 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.101s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6441039,"delete_count":0,"lbm_write_time_us":7382,"lbm_writes_lt_1ms":160,"reinsert_count":0,"update_count":785}
I20260812 06:17:06.151577 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=7.149875
I20260812 06:17:06.249735 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.098s	user 0.025s	sys 0.004s Metrics: {"bytes_written":8902497,"delete_count":0,"lbm_write_time_us":12900,"lbm_writes_lt_1ms":220,"reinsert_count":0,"update_count":1085}
I20260812 06:17:06.250607 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:06.352245 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.101s	user 0.031s	sys 0.003s Metrics: {"bytes_written":8369178,"delete_count":0,"lbm_write_time_us":14359,"lbm_writes_lt_1ms":207,"reinsert_count":0,"update_count":1020}
I20260812 06:17:06.352936 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:06.453522 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.100s	user 0.011s	sys 0.015s Metrics: {"bytes_written":8040983,"delete_count":0,"lbm_write_time_us":11620,"lbm_writes_lt_1ms":199,"reinsert_count":0,"update_count":980}
I20260812 06:17:06.454280 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=7.149875
I20260812 06:17:06.553272 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.099s	user 0.020s	sys 0.004s Metrics: {"bytes_written":9271707,"delete_count":0,"lbm_write_time_us":10390,"lbm_writes_lt_1ms":229,"reinsert_count":0,"update_count":1130}
I20260812 06:17:06.553983 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:06.657858 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.104s	user 0.014s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11173,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:06.658604 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:06.764848 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.106s	user 0.023s	sys 0.007s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":13049,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:06.765432 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:06.864795 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.099s	user 0.030s	sys 0.000s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":13273,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:06.865653 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:06.970487 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.105s	user 0.023s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11392,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:06.971163 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=7.149875
I20260812 06:17:07.072542 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.101s	user 0.018s	sys 0.005s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9626,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:07.073341 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:07.170362 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.097s	user 0.023s	sys 0.004s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":11980,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:07.171195 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:07.271260 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.100s	user 0.022s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10750,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":1000}
I20260812 06:17:07.272186 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=6.157687
I20260812 06:17:07.305749 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.033s	user 0.020s	sys 0.008s Metrics: {"bytes_written":8287127,"delete_count":0,"lbm_write_time_us":12971,"lbm_writes_lt_1ms":205,"reinsert_count":0,"update_count":1010}
I20260812 06:17:07.306329 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=2.188937
I20260812 06:17:07.339169 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.032s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4614,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:07.339743 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushMRSOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=1.000000
I20260812 06:17:07.395449 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushMRSOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.056s	user 0.031s	sys 0.004s Metrics: {"bytes_written":1808273,"cfile_init":1,"dirs.queue_time_us":995,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1350,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2577,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":44,"thread_start_us":140,"threads_started":1}
I20260812 06:17:07.396140 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling LogGCOp(af1ecde8438143d5b0044a6c96d1b7ad): free 174553350 bytes of WAL
I20260812 06:17:07.396413 32524 log_reader.cc:385] T af1ecde8438143d5b0044a6c96d1b7ad: removed 17 log segments from log reader
I20260812 06:17:07.396461 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000001 (ops 1-6)
I20260812 06:17:07.396494 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000002 (ops 7-11)
I20260812 06:17:07.396570 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000003 (ops 12-16)
I20260812 06:17:07.396620 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000004 (ops 17-21)
I20260812 06:17:07.396663 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000005 (ops 22-26)
I20260812 06:17:07.396683 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000006 (ops 27-31)
I20260812 06:17:07.396757 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000007 (ops 32-36)
I20260812 06:17:07.396804 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000008 (ops 37-41)
I20260812 06:17:07.396868 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000009 (ops 42-46)
I20260812 06:17:07.396912 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000010 (ops 47-51)
I20260812 06:17:07.396955 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000011 (ops 52-56)
I20260812 06:17:07.396997 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000012 (ops 57-61)
I20260812 06:17:07.397039 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000013 (ops 62-66)
I20260812 06:17:07.397081 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000014 (ops 67-70)
I20260812 06:17:07.397123 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000015 (ops 71-75)
I20260812 06:17:07.397171 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000016 (ops 76-80)
I20260812 06:17:07.397212 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000017 (ops 81-85)
I20260812 06:17:07.438475 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: LogGCOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.042s	user 0.000s	sys 0.038s Metrics: {}
I20260812 06:17:07.439116 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=10.126437
I20260812 06:17:07.492902 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.054s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18851,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.493432 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling LogGCOp(af1ecde8438143d5b0044a6c96d1b7ad): free 12017939 bytes of WAL
I20260812 06:17:07.493656 32524 log_reader.cc:385] T af1ecde8438143d5b0044a6c96d1b7ad: removed 1 log segments from log reader
I20260812 06:17:07.493702 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000018 (ops 86-90)
I20260812 06:17:07.496187 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: LogGCOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:07.496529 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling UndoDeltaBlockGCOp(af1ecde8438143d5b0044a6c96d1b7ad): 628 bytes on disk
I20260812 06:17:07.496965 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: UndoDeltaBlockGCOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:07.497437 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=2.188937
I20260812 06:17:07.512166 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.512882 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling MajorDeltaCompactionOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=1.000000
I20260812 06:17:09.398699 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: MajorDeltaCompactionOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 1.886s	user 0.907s	sys 0.962s Metrics: {"cfile_cache_miss":4755,"cfile_cache_miss_bytes":196914857,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":25,"delta_iterators_relevant":25,"dirs.queue_time_us":1232,"lbm_read_time_us":90053,"lbm_reads_lt_1ms":4791,"lbm_write_time_us":564317,"lbm_writes_1-10_ms":8,"lbm_writes_lt_1ms":4739,"peak_mem_usage":585031924,"reinsert_count":0,"spinlock_wait_cycles":84352,"thread_start_us":510,"threads_started":7,"update_count":23500}
I20260812 06:17:09.399541 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=95.454562
I20260812 06:17:09.832613 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.433s	user 0.199s	sys 0.101s Metrics: {"bytes_written":100058211,"delete_count":0,"lbm_write_time_us":150564,"lbm_writes_lt_1ms":2444,"reinsert_count":0,"update_count":12195}
I20260812 06:17:09.833261 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=28.978000
I20260812 06:17:10.027838 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.194s	user 0.065s	sys 0.032s Metrics: {"bytes_written":31219614,"delete_count":0,"lbm_write_time_us":45177,"lbm_writes_lt_1ms":764,"mutex_wait_us":3,"reinsert_count":0,"update_count":3805}
I20260812 06:17:10.028765 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=11.118625
I20260812 06:17:10.173584 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.145s	user 0.089s	sys 0.034s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":55816,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:10.176759 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=2.188937
I20260812 06:17:10.226989 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.050s	user 0.037s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":20169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.228801 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=2.188937
I20260812 06:17:10.270989 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.042s	user 0.021s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":15298,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.273126 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushMRSOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=1.000000
I20260812 06:17:10.357616 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushMRSOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.084s	user 0.067s	sys 0.014s Metrics: {"bytes_written":1644369,"cfile_init":1,"dirs.queue_time_us":169,"dirs.run_cpu_time_us":621,"dirs.run_wall_time_us":2419,"drs_written":1,"lbm_read_time_us":152,"lbm_reads_lt_1ms":4,"lbm_write_time_us":6829,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":40}
I20260812 06:17:10.360322 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=2.188937
I20260812 06:17:10.396812 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.036s	user 0.014s	sys 0.020s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":16165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.397877 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling LogGCOp(af1ecde8438143d5b0044a6c96d1b7ad): free 162576719 bytes of WAL
I20260812 06:17:10.398564 32524 log_reader.cc:385] T af1ecde8438143d5b0044a6c96d1b7ad: removed 16 log segments from log reader
I20260812 06:17:10.398641 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000019 (ops 91-95)
I20260812 06:17:10.398725 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000020 (ops 96-100)
I20260812 06:17:10.398870 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000021 (ops 101-105)
I20260812 06:17:10.399152 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000022 (ops 106-110)
I20260812 06:17:10.399295 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000023 (ops 111-115)
I20260812 06:17:10.399392 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000024 (ops 116-120)
I20260812 06:17:10.399495 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000025 (ops 121-125)
I20260812 06:17:10.399596 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000026 (ops 126-130)
I20260812 06:17:10.399673 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000027 (ops 131-135)
I20260812 06:17:10.399912 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000028 (ops 136-140)
I20260812 06:17:10.400032 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000029 (ops 141-145)
I20260812 06:17:10.400163 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000030 (ops 146-150)
I20260812 06:17:10.400259 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000031 (ops 151-154)
I20260812 06:17:10.400385 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000032 (ops 155-159)
I20260812 06:17:10.400498 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000033 (ops 160-164)
I20260812 06:17:10.400741 32524 log.cc:1079] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: Deleting log segment in path: /tmp/dist-test-task1iR9pb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515418672420-32167-0/minicluster-data/ts-0-root/wals/af1ecde8438143d5b0044a6c96d1b7ad/wal-000000034 (ops 165-169)
I20260812 06:17:10.503422 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: LogGCOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.105s	user 0.002s	sys 0.098s Metrics: {}
I20260812 06:17:10.504743 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling UndoDeltaBlockGCOp(af1ecde8438143d5b0044a6c96d1b7ad): 584 bytes on disk
I20260812 06:17:10.506174 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: UndoDeltaBlockGCOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":278,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.507915 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=1.000000
I20260812 06:17:10.532536 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.024s	user 0.012s	sys 0.009s Metrics: {"bytes_written":1846281,"delete_count":0,"lbm_write_time_us":7521,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:17:10.534047 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=1.196750
I20260812 06:17:10.561206 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.027s	user 0.012s	sys 0.012s Metrics: {"bytes_written":2256529,"delete_count":0,"lbm_write_time_us":9769,"lbm_writes_lt_1ms":58,"reinsert_count":0,"update_count":275}
I20260812 06:17:10.562563 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling MajorDeltaCompactionOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=1.000000
I20260812 06:17:12.113966 32167 heavy-update-compaction-itest.cc:229] Time spent updating: real 7.022s	user 2.179s	sys 0.210s
I20260812 06:17:12.462990 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: MajorDeltaCompactionOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 1.900s	user 1.125s	sys 0.769s Metrics: {"cfile_cache_miss":3940,"cfile_cache_miss_bytes":164093559,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":8,"delta_iterators_relevant":8,"lbm_read_time_us":239941,"lbm_reads_1-10_ms":2,"lbm_reads_lt_1ms":3974,"lbm_write_time_us":202211,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":3943,"peak_mem_usage":485619348,"reinsert_count":0,"spinlock_wait_cycles":95872,"update_count":19500}
I20260812 06:17:12.463709 32604 maintenance_manager.cc:419] P b3fd01e1cf8d4735b6beaaad035cb44b: Scheduling FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad): perf score=53.782687
I20260812 06:17:12.516832 32167 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.402s	user 0.003s	sys 0.000s
I20260812 06:17:12.517932 32167 tablet_server.cc:179] TabletServer@127.31.105.193:0 shutting down...
I20260812 06:17:12.617982 32524 maintenance_manager.cc:643] P b3fd01e1cf8d4735b6beaaad035cb44b: FlushDeltaMemStoresOp(af1ecde8438143d5b0044a6c96d1b7ad) complete. Timing: real 0.154s	user 0.086s	sys 0.055s Metrics: {"bytes_written":57434030,"delete_count":0,"lbm_write_time_us":59769,"lbm_writes_lt_1ms":1403,"reinsert_count":0,"update_count":7000}
I20260812 06:17:12.618716 32167 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:12.618988 32167 tablet_replica.cc:333] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b: stopping tablet replica
I20260812 06:17:12.619155 32167 raft_consensus.cc:2243] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:12.619303 32167 raft_consensus.cc:2272] T af1ecde8438143d5b0044a6c96d1b7ad P b3fd01e1cf8d4735b6beaaad035cb44b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:12.633906 32167 tablet_server.cc:196] TabletServer@127.31.105.193:0 shutdown complete.
I20260812 06:17:13.096411 32167 master.cc:562] Master@127.31.105.254:45093 shutting down...
I20260812 06:17:13.101109 32167 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:13.101342 32167 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:13.101423 32167 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3177dc40aab54aeeaef38b33956e588a: stopping tablet replica
I20260812 06:17:13.114257 32167 master.cc:584] Master@127.31.105.254:45093 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (8506 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (14537 ms total)

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