[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:09.621418 12366 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.19.190:43119
I20260812 06:19:09.623291 12366 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:09.624145 12366 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:09.633103 12376 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:09.633239 12378 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:09.633504 12366 server_base.cc:1061] running on GCE node
W20260812 06:19:09.633577 12375 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:09.634230 12366 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:09.634346 12366 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:09.634377 12366 hybrid_clock.cc:648] HybridClock initialized: now 1786515549634375 us; error 0 us; skew 500 ppm
I20260812 06:19:09.636711 12366 webserver.cc:533] Webserver started at http://127.12.19.190:42237/ using document root <none> and password file <none>
I20260812 06:19:09.638245 12366 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:09.638353 12366 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:09.638662 12366 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:09.640661 12366 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/master-0-root/instance:
uuid: "e1e865241b404725bfcbab3930bdc72b"
format_stamp: "Formatted at 2026-08-12 06:19:09 on dist-test-slave-vxj2"
I20260812 06:19:09.645606 12366 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.008s	sys 0.000s
I20260812 06:19:09.648439 12383 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:09.649919 12366 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:09.650138 12366 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/master-0-root
uuid: "e1e865241b404725bfcbab3930bdc72b"
format_stamp: "Formatted at 2026-08-12 06:19:09 on dist-test-slave-vxj2"
I20260812 06:19:09.650291 12366 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:09.673314 12366 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:09.674098 12366 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:09.674324 12366 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:09.684362 12366 rpc_server.cc:307] RPC server started. Bound to: 127.12.19.190:43119
I20260812 06:19:09.684384 12447 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.19.190:43119 every 8 connection(s)
I20260812 06:19:09.687318 12448 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:09.694033 12448 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b: Bootstrap starting.
I20260812 06:19:09.696898 12448 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:09.698522 12448 log.cc:826] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:09.701213 12448 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b: No bootstrap required, opened a new log
I20260812 06:19:09.704792 12448 raft_consensus.cc:359] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1e865241b404725bfcbab3930bdc72b" member_type: VOTER }
I20260812 06:19:09.705065 12448 raft_consensus.cc:385] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:09.705116 12448 raft_consensus.cc:740] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e1e865241b404725bfcbab3930bdc72b, State: Initialized, Role: FOLLOWER
I20260812 06:19:09.705894 12448 consensus_queue.cc:260] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [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: "e1e865241b404725bfcbab3930bdc72b" member_type: VOTER }
I20260812 06:19:09.706185 12448 raft_consensus.cc:399] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:09.706293 12448 raft_consensus.cc:493] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:09.706477 12448 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:09.707474 12448 raft_consensus.cc:515] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1e865241b404725bfcbab3930bdc72b" member_type: VOTER }
I20260812 06:19:09.708076 12448 leader_election.cc:304] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [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: e1e865241b404725bfcbab3930bdc72b; no voters: 
I20260812 06:19:09.708482 12448 leader_election.cc:290] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:09.708855 12454 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:09.709218 12454 raft_consensus.cc:697] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 1 LEADER]: Becoming Leader. State: Replica: e1e865241b404725bfcbab3930bdc72b, State: Running, Role: LEADER
I20260812 06:19:09.709731 12454 consensus_queue.cc:237] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [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: "e1e865241b404725bfcbab3930bdc72b" member_type: VOTER }
I20260812 06:19:09.710211 12448 sys_catalog.cc:565] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:09.712222 12457 sys_catalog.cc:455] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [sys.catalog]: SysCatalogTable state changed. Reason: New leader e1e865241b404725bfcbab3930bdc72b. Latest consensus state: current_term: 1 leader_uuid: "e1e865241b404725bfcbab3930bdc72b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1e865241b404725bfcbab3930bdc72b" member_type: VOTER } }
I20260812 06:19:09.712263 12455 sys_catalog.cc:455] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e1e865241b404725bfcbab3930bdc72b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1e865241b404725bfcbab3930bdc72b" member_type: VOTER } }
I20260812 06:19:09.712379 12457 sys_catalog.cc:458] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:09.712383 12455 sys_catalog.cc:458] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:09.712828 12466 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:09.716154 12466 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:09.716555 12366 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:09.723273 12466 catalog_manager.cc:1383] Generated new cluster ID: 460d0c227ce2429abf9e4d4ca7e3936e
I20260812 06:19:09.723394 12466 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:09.742481 12466 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:09.743561 12466 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:09.762482 12466 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b: Generated new TSK 0
I20260812 06:19:09.763540 12466 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:09.782173 12366 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:09.785702 12476 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:09.785904 12480 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:09.785904 12477 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:09.786113 12366 server_base.cc:1061] running on GCE node
I20260812 06:19:09.786428 12366 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:09.786504 12366 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:09.786525 12366 hybrid_clock.cc:648] HybridClock initialized: now 1786515549786524 us; error 0 us; skew 500 ppm
I20260812 06:19:09.787652 12366 webserver.cc:533] Webserver started at http://127.12.19.129:35961/ using document root <none> and password file <none>
I20260812 06:19:09.787873 12366 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:09.787952 12366 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:09.788051 12366 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:09.788558 12366 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/instance:
uuid: "d5a6444420e74f9dbec2f9ae135769a7"
format_stamp: "Formatted at 2026-08-12 06:19:09 on dist-test-slave-vxj2"
I20260812 06:19:09.790448 12366 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:19:09.791640 12486 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:09.791954 12366 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:09.792027 12366 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root
uuid: "d5a6444420e74f9dbec2f9ae135769a7"
format_stamp: "Formatted at 2026-08-12 06:19:09 on dist-test-slave-vxj2"
I20260812 06:19:09.792135 12366 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:09.807477 12366 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:09.808099 12366 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:09.808699 12366 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:09.809844 12366 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:09.809913 12366 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:09.809988 12366 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:09.810029 12366 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:09.818969 12366 rpc_server.cc:307] RPC server started. Bound to: 127.12.19.129:32823
I20260812 06:19:09.819054 12560 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.19.129:32823 every 8 connection(s)
I20260812 06:19:09.831414 12561 heartbeater.cc:344] Connected to a master server at 127.12.19.190:43119
I20260812 06:19:09.831736 12561 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:09.832253 12561 heartbeater.cc:507] Master 127.12.19.190:43119 requested a full tablet report, sending...
I20260812 06:19:09.834077 12406 ts_manager.cc:194] Registered new tserver with Master: d5a6444420e74f9dbec2f9ae135769a7 (127.12.19.129:32823)
I20260812 06:19:09.834690 12366 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014916244s
I20260812 06:19:09.835734 12406 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45322
I20260812 06:19:09.846748 12406 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45330:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:09.865567 12518 tablet_service.cc:1511] Processing CreateTablet for tablet cad44ac89a024f3a87230807073469b4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ac9b281473354af19ef7ddfb0ecbe0fc]), partition=
I20260812 06:19:09.866107 12518 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cad44ac89a024f3a87230807073469b4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:09.869098 12575 tablet_bootstrap.cc:492] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Bootstrap starting.
I20260812 06:19:09.870277 12575 tablet_bootstrap.cc:654] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:09.871608 12575 tablet_bootstrap.cc:492] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: No bootstrap required, opened a new log
I20260812 06:19:09.871778 12575 ts_tablet_manager.cc:1403] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:09.872575 12575 raft_consensus.cc:359] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d5a6444420e74f9dbec2f9ae135769a7" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 32823 } }
I20260812 06:19:09.872726 12575 raft_consensus.cc:385] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:09.872771 12575 raft_consensus.cc:740] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d5a6444420e74f9dbec2f9ae135769a7, State: Initialized, Role: FOLLOWER
I20260812 06:19:09.872972 12575 consensus_queue.cc:260] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [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: "d5a6444420e74f9dbec2f9ae135769a7" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 32823 } }
I20260812 06:19:09.873134 12575 raft_consensus.cc:399] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:09.873211 12575 raft_consensus.cc:493] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:09.873279 12575 raft_consensus.cc:3060] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:09.874164 12575 raft_consensus.cc:515] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d5a6444420e74f9dbec2f9ae135769a7" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 32823 } }
I20260812 06:19:09.874310 12575 leader_election.cc:304] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [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: d5a6444420e74f9dbec2f9ae135769a7; no voters: 
I20260812 06:19:09.874639 12575 leader_election.cc:290] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:09.874773 12577 raft_consensus.cc:2804] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:09.875021 12577 raft_consensus.cc:697] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 1 LEADER]: Becoming Leader. State: Replica: d5a6444420e74f9dbec2f9ae135769a7, State: Running, Role: LEADER
I20260812 06:19:09.875059 12575 ts_tablet_manager.cc:1434] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:19:09.875319 12577 consensus_queue.cc:237] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [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: "d5a6444420e74f9dbec2f9ae135769a7" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 32823 } }
I20260812 06:19:09.875399 12561 heartbeater.cc:499] Master 127.12.19.190:43119 was elected leader, sending a full tablet report...
I20260812 06:19:09.879385 12405 catalog_manager.cc:5719] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 reported cstate change: term changed from 0 to 1, leader changed from <none> to d5a6444420e74f9dbec2f9ae135769a7 (127.12.19.129). New cstate: current_term: 1 leader_uuid: "d5a6444420e74f9dbec2f9ae135769a7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d5a6444420e74f9dbec2f9ae135769a7" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 32823 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:09.955374 12366 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.015s	sys 0.015s
I20260812 06:19:10.070516 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushMRSOp(cad44ac89a024f3a87230807073469b4): perf score=10.125253
I20260812 06:19:10.249251 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushMRSOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.178s	user 0.133s	sys 0.036s Metrics: {"bytes_written":12307492,"cfile_init":1,"compiler_manager_pool.queue_time_us":360,"delete_count":0,"dirs.queue_time_us":131,"dirs.run_cpu_time_us":452,"dirs.run_wall_time_us":1703,"drs_written":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37865,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":211,"threads_started":1,"update_count":1500}
I20260812 06:19:10.250483 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling LogGCOp(cad44ac89a024f3a87230807073469b4): free 11976772 bytes of WAL
I20260812 06:19:10.250844 12492 log_reader.cc:385] T cad44ac89a024f3a87230807073469b4: removed 1 log segments from log reader
I20260812 06:19:10.250926 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000001 (ops 1-6)
I20260812 06:19:10.254526 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: LogGCOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:10.255057 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling UndoDeltaBlockGCOp(cad44ac89a024f3a87230807073469b4): 8206537 bytes on disk
I20260812 06:19:10.255770 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: UndoDeltaBlockGCOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.256256 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:10.274731 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.018s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6734,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.275388 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:10.428099 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.152s	user 0.128s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":886,"lbm_read_time_us":8878,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30283,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":401,"threads_started":5,"update_count":2000}
I20260812 06:19:10.428970 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=7.149875
I20260812 06:19:10.454064 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.025s	user 0.016s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10723,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:10.454874 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:10.466996 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4506,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:10.467675 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:10.592532 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.125s	user 0.103s	sys 0.020s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487926,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1245,"lbm_read_time_us":8682,"lbm_reads_lt_1ms":372,"lbm_write_time_us":23187,"lbm_writes_lt_1ms":343,"mutex_wait_us":362,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":26624,"update_count":1500}
I20260812 06:19:10.593190 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=7.149875
I20260812 06:19:10.627552 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.034s	user 0.023s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14884,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:10.628262 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:10.642983 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5080,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:10.643523 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:10.764575 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.121s	user 0.102s	sys 0.016s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487926,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":747,"lbm_read_time_us":7338,"lbm_reads_lt_1ms":364,"lbm_write_time_us":21087,"lbm_writes_lt_1ms":343,"mutex_wait_us":302,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:10.765133 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:10.805342 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17779,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.805924 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:10.930126 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.124s	user 0.093s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487816,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":276,"lbm_read_time_us":7237,"lbm_reads_lt_1ms":367,"lbm_write_time_us":22293,"lbm_writes_lt_1ms":343,"mutex_wait_us":64,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.930730 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:10.982164 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.051s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18077,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.982851 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:10.996168 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.996731 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:11.137367 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.140s	user 0.120s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":973,"lbm_read_time_us":9704,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28176,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.138072 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:11.183429 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.045s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18226,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.184029 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:11.195370 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.196118 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:11.330231 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.134s	user 0.110s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":211,"lbm_read_time_us":9878,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26189,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":87680,"update_count":2000}
I20260812 06:19:11.331084 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:11.379106 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.048s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18009,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.379711 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:11.395181 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.395814 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:11.536772 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.141s	user 0.108s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":378,"lbm_read_time_us":9742,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27504,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:19:11.537379 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:11.587437 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.050s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14958,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.588330 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:11.599792 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4312,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.600319 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushMRSOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:11.637466 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushMRSOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.037s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":434,"dirs.run_wall_time_us":1978,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1523,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:11.638717 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:11.825829 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.187s	user 0.115s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":12002,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31502,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.826742 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling LogGCOp(cad44ac89a024f3a87230807073469b4): free 121006426 bytes of WAL
I20260812 06:19:11.827136 12492 log_reader.cc:385] T cad44ac89a024f3a87230807073469b4: removed 12 log segments from log reader
I20260812 06:19:11.827222 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000002 (ops 7-11)
I20260812 06:19:11.827281 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000003 (ops 12-16)
I20260812 06:19:11.827329 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000004 (ops 17-21)
I20260812 06:19:11.827375 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000005 (ops 22-26)
I20260812 06:19:11.827419 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000006 (ops 27-31)
I20260812 06:19:11.827487 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000007 (ops 32-36)
I20260812 06:19:11.827533 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000008 (ops 37-41)
I20260812 06:19:11.827589 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000009 (ops 42-46)
I20260812 06:19:11.827636 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000010 (ops 47-50)
I20260812 06:19:11.827678 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000011 (ops 51-55)
I20260812 06:19:11.827721 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000012 (ops 56-60)
I20260812 06:19:11.827769 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000013 (ops 61-65)
I20260812 06:19:11.858254 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: LogGCOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.031s	user 0.007s	sys 0.023s Metrics: {}
I20260812 06:19:11.858777 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling UndoDeltaBlockGCOp(cad44ac89a024f3a87230807073469b4): 463 bytes on disk
I20260812 06:19:11.859475 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: UndoDeltaBlockGCOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"spinlock_wait_cycles":21888}
I20260812 06:19:11.860137 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=14.095187
I20260812 06:19:11.900938 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.041s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17390,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.901621 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:11.936198 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.034s	user 0.001s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.936867 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:11.948138 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4338,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.948874 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:12.158582 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.209s	user 0.146s	sys 0.061s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795290,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":489,"lbm_read_time_us":14619,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35771,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3000}
I20260812 06:19:12.159282 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=14.095187
I20260812 06:19:12.225400 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.066s	user 0.044s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23118,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.226070 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:12.243198 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.243937 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:12.447744 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.204s	user 0.142s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":376,"lbm_read_time_us":20136,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31303,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24576,"update_count":2500}
I20260812 06:19:12.448398 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:12.502645 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.054s	user 0.030s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20798,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.503546 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:12.518127 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.014s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.518674 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:12.664160 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.145s	user 0.116s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":361,"lbm_read_time_us":11519,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24342,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:19:12.664986 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:12.712926 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.048s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17066,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.713593 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:12.725790 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.726521 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:12.865193 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.138s	user 0.128s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":329,"lbm_read_time_us":10468,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27036,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:19:12.866037 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:12.915798 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.049s	user 0.034s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21043,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.916380 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:12.930395 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4838,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.930951 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:13.065207 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.134s	user 0.118s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1008,"lbm_read_time_us":8499,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26403,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:13.066053 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:13.115515 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.049s	user 0.020s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17412,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:13.116182 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:13.127560 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.128317 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:13.288764 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.160s	user 0.112s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":56,"lbm_read_time_us":12019,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27303,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:19:13.289945 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=11.118625
I20260812 06:19:13.328116 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.038s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16496,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:13.328840 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:13.345067 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6181,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:13.345690 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushMRSOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:13.380563 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushMRSOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":113,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1754,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1643,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:13.382596 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling LogGCOp(cad44ac89a024f3a87230807073469b4): free 120553331 bytes of WAL
I20260812 06:19:13.382959 12492 log_reader.cc:385] T cad44ac89a024f3a87230807073469b4: removed 12 log segments from log reader
I20260812 06:19:13.383035 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000014 (ops 66-70)
I20260812 06:19:13.383092 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000015 (ops 71-74)
I20260812 06:19:13.383138 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000016 (ops 75-79)
I20260812 06:19:13.383183 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000017 (ops 80-84)
I20260812 06:19:13.383229 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000018 (ops 85-89)
I20260812 06:19:13.383270 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000019 (ops 90-94)
I20260812 06:19:13.383314 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000020 (ops 95-99)
I20260812 06:19:13.383359 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000021 (ops 100-104)
I20260812 06:19:13.383400 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000022 (ops 105-109)
I20260812 06:19:13.383445 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000023 (ops 110-114)
I20260812 06:19:13.383491 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000024 (ops 115-118)
I20260812 06:19:13.383531 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000025 (ops 119-123)
I20260812 06:19:13.414337 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: LogGCOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:13.414844 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling UndoDeltaBlockGCOp(cad44ac89a024f3a87230807073469b4): 483 bytes on disk
I20260812 06:19:13.415454 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: UndoDeltaBlockGCOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:13.416126 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=4.173312
I20260812 06:19:13.444537 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.028s	user 0.017s	sys 0.007s Metrics: {"bytes_written":5825680,"delete_count":0,"lbm_write_time_us":7490,"lbm_writes_lt_1ms":145,"reinsert_count":0,"update_count":710}
I20260812 06:19:13.445344 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling LogGCOp(cad44ac89a024f3a87230807073469b4): free 12017983 bytes of WAL
I20260812 06:19:13.445604 12492 log_reader.cc:385] T cad44ac89a024f3a87230807073469b4: removed 1 log segments from log reader
I20260812 06:19:13.445672 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000026 (ops 124-128)
I20260812 06:19:13.448238 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: LogGCOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:13.448733 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=1.196750
I20260812 06:19:13.457121 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":2379604,"delete_count":0,"lbm_write_time_us":2571,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:19:13.457736 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:13.661613 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.204s	user 0.125s	sys 0.078s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":295,"lbm_read_time_us":15365,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33173,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:19:13.662565 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=14.095187
I20260812 06:19:13.726682 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.064s	user 0.024s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23156,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.727588 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:13.739090 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4416,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.739816 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:13.939670 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.200s	user 0.142s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1597,"lbm_read_time_us":14145,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33154,"lbm_writes_lt_1ms":543,"mutex_wait_us":597,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:19:13.940455 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=11.118625
I20260812 06:19:13.991851 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.051s	user 0.032s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":24025,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:13.992642 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:14.021075 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.028s	user 0.013s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4607,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:14.021811 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:14.033070 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4190,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.033686 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:14.245744 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.212s	user 0.131s	sys 0.067s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692869,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":176,"lbm_read_time_us":14516,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33394,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":104192,"update_count":2500}
I20260812 06:19:14.246493 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=14.095187
I20260812 06:19:14.306231 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.060s	user 0.027s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28371,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:14.306926 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:14.318918 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.319600 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:14.532207 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.212s	user 0.137s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":469,"lbm_read_time_us":13112,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32680,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:19:14.533016 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=11.118625
I20260812 06:19:14.595350 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.062s	user 0.035s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":25606,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:14.596140 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:14.611840 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.612423 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:14.623704 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3893,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:14.624300 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:14.787845 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.163s	user 0.120s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692870,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1201,"lbm_read_time_us":11244,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32692,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:19:14.788693 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=11.118625
I20260812 06:19:14.834118 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.045s	user 0.044s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19409,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:14.834693 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:14.847580 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5058,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:14.848327 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:14.996516 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.148s	user 0.107s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1349,"lbm_read_time_us":10366,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28636,"lbm_writes_lt_1ms":443,"mutex_wait_us":595,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:19:14.997303 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=10.126437
I20260812 06:19:15.056842 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.059s	user 0.030s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21199,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:19:15.057700 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:15.070669 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.013s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4410,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.071440 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushMRSOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:15.104017 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushMRSOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":2304,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2287,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:15.105228 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling LogGCOp(cad44ac89a024f3a87230807073469b4): free 121006699 bytes of WAL
I20260812 06:19:15.105599 12492 log_reader.cc:385] T cad44ac89a024f3a87230807073469b4: removed 12 log segments from log reader
I20260812 06:19:15.105670 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000027 (ops 129-133)
I20260812 06:19:15.105715 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000028 (ops 134-138)
I20260812 06:19:15.105738 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000029 (ops 139-143)
I20260812 06:19:15.105773 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000030 (ops 144-148)
I20260812 06:19:15.105805 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000031 (ops 149-153)
I20260812 06:19:15.105834 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000032 (ops 154-158)
I20260812 06:19:15.105858 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000033 (ops 159-163)
I20260812 06:19:15.105887 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000034 (ops 164-168)
I20260812 06:19:15.105942 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000035 (ops 169-172)
I20260812 06:19:15.105966 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000036 (ops 173-177)
I20260812 06:19:15.105993 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000037 (ops 178-182)
I20260812 06:19:15.106024 12492 log.cc:1079] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/cad44ac89a024f3a87230807073469b4/wal-000000038 (ops 183-187)
I20260812 06:19:15.142735 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: LogGCOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.037s	user 0.004s	sys 0.032s Metrics: {}
I20260812 06:19:15.143374 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:15.167721 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5732,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.168358 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling UndoDeltaBlockGCOp(cad44ac89a024f3a87230807073469b4): 472 bytes on disk
I20260812 06:19:15.169317 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: UndoDeltaBlockGCOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:15.170085 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:15.182286 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4356,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.183034 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:15.388898 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.206s	user 0.146s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795409,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":692,"lbm_read_time_us":14310,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39443,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:19:15.391382 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=14.095187
I20260812 06:19:15.452668 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.061s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":28218,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.453397 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4): perf score=2.188937
I20260812 06:19:15.473392 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: FlushDeltaMemStoresOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.020s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.474053 12562 maintenance_manager.cc:419] P d5a6444420e74f9dbec2f9ae135769a7: Scheduling MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4): perf score=1.000000
I20260812 06:19:15.495303 12366 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.540s	user 2.025s	sys 0.160s
I20260812 06:19:15.566776 12366 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.003s	sys 0.000s
I20260812 06:19:15.567555 12366 tablet_server.cc:179] TabletServer@127.12.19.129:0 shutting down...
I20260812 06:19:15.621236 12492 maintenance_manager.cc:643] P d5a6444420e74f9dbec2f9ae135769a7: MajorDeltaCompactionOp(cad44ac89a024f3a87230807073469b4) complete. Timing: real 0.147s	user 0.115s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":768,"lbm_read_time_us":10745,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30439,"lbm_writes_lt_1ms":543,"mutex_wait_us":95,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27776,"update_count":2500}
I20260812 06:19:15.622107 12366 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:15.622684 12366 tablet_replica.cc:333] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7: stopping tablet replica
I20260812 06:19:15.622977 12366 raft_consensus.cc:2243] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:15.633508 12366 raft_consensus.cc:2272] T cad44ac89a024f3a87230807073469b4 P d5a6444420e74f9dbec2f9ae135769a7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:15.640699 12366 tablet_server.cc:196] TabletServer@127.12.19.129:0 shutdown complete.
I20260812 06:19:15.669068 12366 master.cc:562] Master@127.12.19.190:43119 shutting down...
I20260812 06:19:15.674988 12366 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:15.675264 12366 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:15.675360 12366 tablet_replica.cc:333] T 00000000000000000000000000000000 P e1e865241b404725bfcbab3930bdc72b: stopping tablet replica
I20260812 06:19:15.688761 12366 master.cc:584] Master@127.12.19.190:43119 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6168 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:15.788722 12366 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.19.190:36099
I20260812 06:19:15.789243 12366 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:15.791632 12596 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:15.791754 12595 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:15.791695 12599 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:15.791846 12366 server_base.cc:1061] running on GCE node
I20260812 06:19:15.792109 12366 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:15.792153 12366 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:15.792169 12366 hybrid_clock.cc:648] HybridClock initialized: now 1786515555792169 us; error 0 us; skew 500 ppm
I20260812 06:19:15.793079 12366 webserver.cc:533] Webserver started at http://127.12.19.190:38193/ using document root <none> and password file <none>
I20260812 06:19:15.793365 12366 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:15.793413 12366 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:15.793473 12366 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:15.793874 12366 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/master-0-root/instance:
uuid: "d29bad0f03ac4088ace4a9c34a471d77"
format_stamp: "Formatted at 2026-08-12 06:19:15 on dist-test-slave-vxj2"
I20260812 06:19:15.795785 12366 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:15.797286 12606 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:15.797765 12366 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:15.797881 12366 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/master-0-root
uuid: "d29bad0f03ac4088ace4a9c34a471d77"
format_stamp: "Formatted at 2026-08-12 06:19:15 on dist-test-slave-vxj2"
I20260812 06:19:15.798012 12366 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:15.809449 12366 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:15.809935 12366 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:15.815342 12366 rpc_server.cc:307] RPC server started. Bound to: 127.12.19.190:36099
I20260812 06:19:15.817142 12670 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.19.190:36099 every 8 connection(s)
I20260812 06:19:15.817708 12671 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:15.823383 12671 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77: Bootstrap starting.
I20260812 06:19:15.824378 12671 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:15.825723 12671 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77: No bootstrap required, opened a new log
I20260812 06:19:15.826500 12671 raft_consensus.cc:359] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d29bad0f03ac4088ace4a9c34a471d77" member_type: VOTER }
I20260812 06:19:15.826682 12671 raft_consensus.cc:385] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:15.826769 12671 raft_consensus.cc:740] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d29bad0f03ac4088ace4a9c34a471d77, State: Initialized, Role: FOLLOWER
I20260812 06:19:15.826988 12671 consensus_queue.cc:260] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [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: "d29bad0f03ac4088ace4a9c34a471d77" member_type: VOTER }
I20260812 06:19:15.827108 12671 raft_consensus.cc:399] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:15.827185 12671 raft_consensus.cc:493] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:15.827293 12671 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:15.828305 12671 raft_consensus.cc:515] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d29bad0f03ac4088ace4a9c34a471d77" member_type: VOTER }
I20260812 06:19:15.828459 12671 leader_election.cc:304] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [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: d29bad0f03ac4088ace4a9c34a471d77; no voters: 
I20260812 06:19:15.828655 12671 leader_election.cc:290] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:15.828945 12674 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:15.829300 12674 raft_consensus.cc:697] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 1 LEADER]: Becoming Leader. State: Replica: d29bad0f03ac4088ace4a9c34a471d77, State: Running, Role: LEADER
I20260812 06:19:15.829311 12671 sys_catalog.cc:565] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:15.829545 12674 consensus_queue.cc:237] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [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: "d29bad0f03ac4088ace4a9c34a471d77" member_type: VOTER }
I20260812 06:19:15.830068 12676 sys_catalog.cc:455] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d29bad0f03ac4088ace4a9c34a471d77. Latest consensus state: current_term: 1 leader_uuid: "d29bad0f03ac4088ace4a9c34a471d77" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d29bad0f03ac4088ace4a9c34a471d77" member_type: VOTER } }
I20260812 06:19:15.830183 12676 sys_catalog.cc:458] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:15.830379 12675 sys_catalog.cc:455] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d29bad0f03ac4088ace4a9c34a471d77" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d29bad0f03ac4088ace4a9c34a471d77" member_type: VOTER } }
I20260812 06:19:15.830473 12675 sys_catalog.cc:458] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:15.830580 12684 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:15.832129 12684 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:15.832368 12366 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:15.834568 12684 catalog_manager.cc:1383] Generated new cluster ID: 7351079d4b8e4819bd9e328188a333f1
I20260812 06:19:15.834666 12684 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:15.866858 12684 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:15.867624 12684 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:15.883940 12684 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77: Generated new TSK 0
I20260812 06:19:15.884229 12684 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:15.897835 12366 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:15.901449 12698 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:15.901476 12695 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:15.901539 12366 server_base.cc:1061] running on GCE node
W20260812 06:19:15.901523 12696 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:15.901978 12366 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:15.902130 12366 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:15.902182 12366 hybrid_clock.cc:648] HybridClock initialized: now 1786515555902182 us; error 0 us; skew 500 ppm
I20260812 06:19:15.903367 12366 webserver.cc:533] Webserver started at http://127.12.19.129:38693/ using document root <none> and password file <none>
I20260812 06:19:15.903530 12366 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:15.903578 12366 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:15.903649 12366 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:15.904306 12366 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/instance:
uuid: "90bf88fef63648429dae3ce97f38f487"
format_stamp: "Formatted at 2026-08-12 06:19:15 on dist-test-slave-vxj2"
I20260812 06:19:15.906644 12366 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:15.907912 12703 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:15.908321 12366 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:15.908406 12366 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root
uuid: "90bf88fef63648429dae3ce97f38f487"
format_stamp: "Formatted at 2026-08-12 06:19:15 on dist-test-slave-vxj2"
I20260812 06:19:15.908480 12366 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:15.922262 12366 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:15.923157 12366 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:15.924243 12366 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:15.925859 12366 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:15.925925 12366 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:15.925984 12366 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:15.926003 12366 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:15.932179 12366 rpc_server.cc:307] RPC server started. Bound to: 127.12.19.129:34417
I20260812 06:19:15.935355 12778 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.19.129:34417 every 8 connection(s)
I20260812 06:19:15.946759 12779 heartbeater.cc:344] Connected to a master server at 127.12.19.190:36099
I20260812 06:19:15.947288 12779 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:15.947686 12779 heartbeater.cc:507] Master 127.12.19.190:36099 requested a full tablet report, sending...
I20260812 06:19:15.948875 12629 ts_manager.cc:194] Registered new tserver with Master: 90bf88fef63648429dae3ce97f38f487 (127.12.19.129:34417)
I20260812 06:19:15.949317 12366 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015503561s
I20260812 06:19:15.949962 12629 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50348
I20260812 06:19:15.963322 12629 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50352:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:15.975464 12735 tablet_service.cc:1511] Processing CreateTablet for tablet 4557cb39c9124ba992c910c4b74815c7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b55eefe0b48f441eb70fe281103866a5]), partition=
I20260812 06:19:15.975811 12735 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4557cb39c9124ba992c910c4b74815c7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:15.980305 12796 tablet_bootstrap.cc:492] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Bootstrap starting.
I20260812 06:19:15.981626 12796 tablet_bootstrap.cc:654] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:15.983273 12796 tablet_bootstrap.cc:492] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: No bootstrap required, opened a new log
I20260812 06:19:15.983520 12796 ts_tablet_manager.cc:1403] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:19:15.985414 12796 raft_consensus.cc:359] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "90bf88fef63648429dae3ce97f38f487" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 34417 } }
I20260812 06:19:15.985821 12796 raft_consensus.cc:385] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:15.986258 12796 raft_consensus.cc:740] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 90bf88fef63648429dae3ce97f38f487, State: Initialized, Role: FOLLOWER
I20260812 06:19:15.986477 12796 consensus_queue.cc:260] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [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: "90bf88fef63648429dae3ce97f38f487" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 34417 } }
I20260812 06:19:15.986639 12796 raft_consensus.cc:399] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:15.986721 12796 raft_consensus.cc:493] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:15.986792 12796 raft_consensus.cc:3060] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:15.988332 12796 raft_consensus.cc:515] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "90bf88fef63648429dae3ce97f38f487" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 34417 } }
I20260812 06:19:15.988540 12796 leader_election.cc:304] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [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: 90bf88fef63648429dae3ce97f38f487; no voters: 
I20260812 06:19:15.989075 12796 leader_election.cc:290] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:15.989583 12799 raft_consensus.cc:2804] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:15.989701 12796 ts_tablet_manager.cc:1434] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Time spent starting tablet: real 0.006s	user 0.007s	sys 0.000s
I20260812 06:19:15.989851 12799 raft_consensus.cc:697] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 1 LEADER]: Becoming Leader. State: Replica: 90bf88fef63648429dae3ce97f38f487, State: Running, Role: LEADER
I20260812 06:19:15.989996 12779 heartbeater.cc:499] Master 127.12.19.190:36099 was elected leader, sending a full tablet report...
I20260812 06:19:15.990042 12799 consensus_queue.cc:237] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [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: "90bf88fef63648429dae3ce97f38f487" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 34417 } }
I20260812 06:19:15.993067 12629 catalog_manager.cc:5719] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 reported cstate change: term changed from 0 to 1, leader changed from <none> to 90bf88fef63648429dae3ce97f38f487 (127.12.19.129). New cstate: current_term: 1 leader_uuid: "90bf88fef63648429dae3ce97f38f487" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "90bf88fef63648429dae3ce97f38f487" member_type: VOTER last_known_addr { host: "127.12.19.129" port: 34417 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:16.079442 12366 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.076s	user 0.016s	sys 0.015s
I20260812 06:19:16.185907 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushMRSOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.125253
I20260812 06:19:16.327697 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushMRSOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.141s	user 0.089s	sys 0.043s Metrics: {"bytes_written":8205078,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1242,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":29322,"lbm_writes_lt_1ms":457,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"update_count":1000}
I20260812 06:19:16.328467 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling LogGCOp(4557cb39c9124ba992c910c4b74815c7): free 11976772 bytes of WAL
I20260812 06:19:16.328723 12708 log_reader.cc:385] T 4557cb39c9124ba992c910c4b74815c7: removed 1 log segments from log reader
I20260812 06:19:16.328769 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000001 (ops 1-6)
I20260812 06:19:16.331586 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: LogGCOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:16.332019 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:16.347275 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.348117 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:16.531361 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.183s	user 0.114s	sys 0.055s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487935,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":494,"lbm_read_time_us":13230,"lbm_reads_lt_1ms":368,"lbm_write_time_us":25328,"lbm_writes_lt_1ms":343,"mutex_wait_us":33,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":14336,"thread_start_us":361,"threads_started":5,"update_count":1500}
I20260812 06:19:16.532043 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling UndoDeltaBlockGCOp(4557cb39c9124ba992c910c4b74815c7): 8206537 bytes on disk
I20260812 06:19:16.532554 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: UndoDeltaBlockGCOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:16.533039 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:16.592617 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.059s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19525,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:16.593364 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:16.606495 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4577,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.607141 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:16.773767 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.166s	user 0.125s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":410,"lbm_read_time_us":9977,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28748,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29568,"update_count":2000}
I20260812 06:19:16.774684 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:16.831416 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.056s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18824,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:16.832059 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:16.843322 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4217,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.843926 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:16.990674 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.147s	user 0.114s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":11076,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26508,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:16.991590 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:17.054792 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.063s	user 0.025s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18769,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.055524 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:17.069075 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5349,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.069725 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:17.243404 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.173s	user 0.101s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":719,"lbm_read_time_us":11389,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24314,"lbm_writes_lt_1ms":443,"mutex_wait_us":480,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21632,"update_count":2000}
I20260812 06:19:17.244319 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:17.299422 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.055s	user 0.028s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18236,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.300017 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:17.314771 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.315238 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:17.479189 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.164s	user 0.142s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2602,"lbm_read_time_us":10178,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31027,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:19:17.480078 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:17.536016 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.056s	user 0.030s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":21087,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.536729 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:17.551760 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.552594 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:17.698756 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.146s	user 0.106s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":434,"lbm_read_time_us":12351,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26518,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:19:17.699433 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:17.764981 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.065s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17843,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.765944 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:17.785037 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.786144 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:17.959686 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.173s	user 0.134s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":14239,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27400,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:17.960515 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:18.007207 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.046s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20144,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:19:18.008035 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:18.021374 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.013s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.022164 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushMRSOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:18.057443 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushMRSOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":312,"dirs.run_wall_time_us":1955,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2338,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:18.058209 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling LogGCOp(4557cb39c9124ba992c910c4b74815c7): free 121006379 bytes of WAL
I20260812 06:19:18.058490 12708 log_reader.cc:385] T 4557cb39c9124ba992c910c4b74815c7: removed 12 log segments from log reader
I20260812 06:19:18.058537 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000002 (ops 7-11)
I20260812 06:19:18.058568 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000003 (ops 12-16)
I20260812 06:19:18.058635 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000004 (ops 17-21)
I20260812 06:19:18.058669 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000005 (ops 22-26)
I20260812 06:19:18.058710 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000006 (ops 27-31)
I20260812 06:19:18.058773 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000007 (ops 32-36)
I20260812 06:19:18.058813 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000008 (ops 37-40)
I20260812 06:19:18.058856 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000009 (ops 41-45)
I20260812 06:19:18.058894 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000010 (ops 46-50)
I20260812 06:19:18.058933 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000011 (ops 51-55)
I20260812 06:19:18.058979 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000012 (ops 56-60)
I20260812 06:19:18.059017 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000013 (ops 61-65)
I20260812 06:19:18.092037 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: LogGCOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.034s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:18.092609 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling UndoDeltaBlockGCOp(4557cb39c9124ba992c910c4b74815c7): 483 bytes on disk
I20260812 06:19:18.093290 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: UndoDeltaBlockGCOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:19:18.093863 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=3.181125
I20260812 06:19:18.121912 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.028s	user 0.008s	sys 0.018s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":6796,"lbm_writes_lt_1ms":131,"mutex_wait_us":187,"reinsert_count":0,"update_count":640}
I20260812 06:19:18.122907 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.196750
I20260812 06:19:18.134712 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":4197,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:19:18.135716 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:18.343434 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.207s	user 0.141s	sys 0.066s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1308,"lbm_read_time_us":15252,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33786,"lbm_writes_lt_1ms":643,"mutex_wait_us":376,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":64640,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:19:18.344219 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=14.095187
I20260812 06:19:18.415659 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.071s	user 0.044s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22189,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.416603 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:18.429476 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.013s	user 0.009s	sys 0.004s 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:19:18.430068 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:18.627507 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.197s	user 0.127s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":14078,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31288,"lbm_writes_lt_1ms":543,"mutex_wait_us":97,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2500}
I20260812 06:19:18.628248 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=11.118625
I20260812 06:19:18.662261 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.034s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14775,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:18.662910 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:18.684887 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.022s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7070,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.685549 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:18.831353 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.145s	user 0.124s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590340,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":10567,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24373,"lbm_writes_lt_1ms":443,"mutex_wait_us":104,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2000}
I20260812 06:19:18.832248 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:18.875528 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.043s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17391,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:18.876303 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:18.889132 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.889789 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:19.021693 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.132s	user 0.104s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1337,"lbm_read_time_us":8523,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25697,"lbm_writes_lt_1ms":443,"mutex_wait_us":335,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30464,"update_count":2000}
I20260812 06:19:19.022526 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:19.075122 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.052s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19040,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.075913 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:19.088205 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4325,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.089112 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:19.238431 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.149s	user 0.116s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":393,"lbm_read_time_us":9621,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28141,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31872,"update_count":2000}
I20260812 06:19:19.239343 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:19.293934 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.054s	user 0.023s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19053,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.294642 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:19.310365 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.015s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.310931 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:19.482234 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.171s	user 0.106s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":705,"lbm_read_time_us":10609,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30585,"lbm_writes_lt_1ms":443,"mutex_wait_us":294,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21632,"update_count":2000}
I20260812 06:19:19.483098 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:19.531746 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.048s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18141,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.532475 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:19.551129 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.552081 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:19.681269 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.129s	user 0.075s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":797,"lbm_read_time_us":8380,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25050,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:19.682385 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:19.728062 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.045s	user 0.028s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19991,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.728787 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:19.741423 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.742576 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushMRSOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:19.782506 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushMRSOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.040s	user 0.038s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":120,"dirs.run_cpu_time_us":364,"dirs.run_wall_time_us":2148,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2483,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:19.783293 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling LogGCOp(4557cb39c9124ba992c910c4b74815c7): free 132571373 bytes of WAL
I20260812 06:19:19.783565 12708 log_reader.cc:385] T 4557cb39c9124ba992c910c4b74815c7: removed 13 log segments from log reader
I20260812 06:19:19.783612 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000014 (ops 66-70)
I20260812 06:19:19.783670 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000015 (ops 71-75)
I20260812 06:19:19.783720 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000016 (ops 76-80)
I20260812 06:19:19.783763 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000017 (ops 81-85)
I20260812 06:19:19.783808 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000018 (ops 86-90)
I20260812 06:19:19.783872 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000019 (ops 91-94)
I20260812 06:19:19.783912 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000020 (ops 95-99)
I20260812 06:19:19.783953 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000021 (ops 100-104)
I20260812 06:19:19.784001 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000022 (ops 105-108)
I20260812 06:19:19.784041 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000023 (ops 109-113)
I20260812 06:19:19.784081 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000024 (ops 114-118)
I20260812 06:19:19.784124 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000025 (ops 119-123)
I20260812 06:19:19.784166 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000026 (ops 124-128)
I20260812 06:19:19.816206 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: LogGCOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:19.816709 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling UndoDeltaBlockGCOp(4557cb39c9124ba992c910c4b74815c7): 483 bytes on disk
I20260812 06:19:19.817539 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: UndoDeltaBlockGCOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:19.818307 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=3.181125
I20260812 06:19:19.832355 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4718025,"delete_count":0,"lbm_write_time_us":5426,"lbm_writes_lt_1ms":118,"reinsert_count":0,"update_count":575}
I20260812 06:19:19.832911 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:19.846035 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":3711,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:19:19.846524 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:20.060015 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.213s	user 0.157s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795395,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2006,"lbm_read_time_us":13929,"lbm_reads_lt_1ms":666,"lbm_write_time_us":41802,"lbm_writes_lt_1ms":643,"mutex_wait_us":923,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:19:20.061580 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=14.095187
I20260812 06:19:20.142023 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.080s	user 0.053s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":36713,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.143206 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:20.164608 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.021s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7414,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.165390 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:20.353530 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.188s	user 0.111s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":608,"lbm_read_time_us":11756,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32380,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:19:20.354223 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=14.095187
I20260812 06:19:20.418948 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.064s	user 0.039s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27511,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.419889 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:20.580852 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.161s	user 0.125s	sys 0.029s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590228,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":361,"lbm_read_time_us":10513,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24681,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35840,"update_count":2000}
I20260812 06:19:20.581734 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=14.095187
I20260812 06:19:20.637334 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.055s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23317,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.637984 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:20.650655 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.012s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4357,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.651299 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:20.870788 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.219s	user 0.135s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":822,"lbm_read_time_us":13860,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35226,"lbm_writes_lt_1ms":543,"mutex_wait_us":363,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38272,"update_count":2500}
I20260812 06:19:20.871520 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=14.095187
I20260812 06:19:20.928406 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.057s	user 0.025s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26415,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.929469 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:20.946928 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.017s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.947654 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:21.122838 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.175s	user 0.118s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":807,"lbm_read_time_us":11236,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33828,"lbm_writes_lt_1ms":543,"mutex_wait_us":261,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:19:21.123864 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=11.118625
I20260812 06:19:21.178278 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.051s	user 0.037s	sys 0.012s Metrics: {"bytes_written":13579241,"delete_count":0,"lbm_write_time_us":21547,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1655}
I20260812 06:19:21.179322 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:21.204663 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.025s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":4596,"lbm_writes_lt_1ms":82,"mutex_wait_us":3,"reinsert_count":0,"update_count":395}
I20260812 06:19:21.205610 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:21.217600 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.218492 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:21.396081 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.177s	user 0.121s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692850,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":600,"lbm_read_time_us":11925,"lbm_reads_lt_1ms":573,"lbm_write_time_us":36697,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:19:21.396797 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=11.118625
I20260812 06:19:21.437533 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12717739,"delete_count":0,"lbm_write_time_us":17583,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:21.438460 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:21.452208 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.013s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4373,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.452769 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushMRSOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:21.514649 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushMRSOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.062s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1869,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2647,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:21.515445 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling LogGCOp(4557cb39c9124ba992c910c4b74815c7): free 128867734 bytes of WAL
I20260812 06:19:21.515703 12708 log_reader.cc:385] T 4557cb39c9124ba992c910c4b74815c7: removed 13 log segments from log reader
I20260812 06:19:21.515758 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000027 (ops 129-133)
I20260812 06:19:21.515789 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000028 (ops 134-138)
I20260812 06:19:21.515836 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000029 (ops 139-143)
I20260812 06:19:21.515892 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000030 (ops 144-148)
I20260812 06:19:21.515937 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000031 (ops 149-152)
I20260812 06:19:21.515986 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000032 (ops 153-157)
I20260812 06:19:21.516059 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000033 (ops 158-162)
I20260812 06:19:21.516104 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000034 (ops 163-166)
I20260812 06:19:21.516149 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000035 (ops 167-171)
I20260812 06:19:21.516192 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000036 (ops 172-176)
I20260812 06:19:21.516232 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000037 (ops 177-181)
I20260812 06:19:21.516299 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000038 (ops 182-186)
I20260812 06:19:21.516361 12708 log.cc:1079] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: Deleting log segment in path: /tmp/dist-test-tasksOgaD2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549608090-12366-0/minicluster-data/ts-0-root/wals/4557cb39c9124ba992c910c4b74815c7/wal-000000039 (ops 187-190)
I20260812 06:19:21.546060 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: LogGCOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:21.546732 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=7.149875
I20260812 06:19:21.572463 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.026s	user 0.015s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10421,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:21.573144 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling UndoDeltaBlockGCOp(4557cb39c9124ba992c910c4b74815c7): 482 bytes on disk
I20260812 06:19:21.573874 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: UndoDeltaBlockGCOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":125,"lbm_reads_lt_1ms":4}
I20260812 06:19:21.574935 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=2.188937
I20260812 06:19:21.599996 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5736,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.600708 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7): perf score=1.000000
I20260812 06:19:21.719770 12366 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.640s	user 2.031s	sys 0.201s
I20260812 06:19:21.825491 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: MajorDeltaCompactionOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.224s	user 0.157s	sys 0.067s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897808,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":744,"lbm_read_time_us":16414,"lbm_reads_lt_1ms":762,"lbm_write_time_us":36389,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":164,"threads_started":1,"update_count":3500}
I20260812 06:19:21.826207 12782 maintenance_manager.cc:419] P 90bf88fef63648429dae3ce97f38f487: Scheduling FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7): perf score=10.126437
I20260812 06:19:21.827140 12366 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.107s	user 0.002s	sys 0.000s
I20260812 06:19:21.827778 12366 tablet_server.cc:179] TabletServer@127.12.19.129:0 shutting down...
I20260812 06:19:21.860401 12708 maintenance_manager.cc:643] P 90bf88fef63648429dae3ce97f38f487: FlushDeltaMemStoresOp(4557cb39c9124ba992c910c4b74815c7) complete. Timing: real 0.034s	user 0.017s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14902,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.861434 12366 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:21.861685 12366 tablet_replica.cc:333] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487: stopping tablet replica
I20260812 06:19:21.861881 12366 raft_consensus.cc:2243] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:21.862082 12366 raft_consensus.cc:2272] T 4557cb39c9124ba992c910c4b74815c7 P 90bf88fef63648429dae3ce97f38f487 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:21.867419 12366 tablet_server.cc:196] TabletServer@127.12.19.129:0 shutdown complete.
I20260812 06:19:21.884686 12366 master.cc:562] Master@127.12.19.190:36099 shutting down...
I20260812 06:19:21.888746 12366 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:21.888952 12366 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:21.889000 12366 tablet_replica.cc:333] T 00000000000000000000000000000000 P d29bad0f03ac4088ace4a9c34a471d77: stopping tablet replica
I20260812 06:19:21.904347 12366 master.cc:584] Master@127.12.19.190:36099 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6209 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12379 ms total)

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