[==========] 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:17:54.086725 31307 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.146.254:35253
I20260812 06:17:54.087980 31307 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:17:54.088616 31307 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:54.095232 31314 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:54.095269 31312 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:54.095290 31307 server_base.cc:1061] running on GCE node
W20260812 06:17:54.095587 31316 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:54.096089 31307 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:54.096199 31307 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:54.096243 31307 hybrid_clock.cc:648] HybridClock initialized: now 1786515474096242 us; error 0 us; skew 500 ppm
I20260812 06:17:54.097900 31307 webserver.cc:533] Webserver started at http://127.30.146.254:34515/ using document root <none> and password file <none>
I20260812 06:17:54.098475 31307 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:54.098552 31307 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:54.098794 31307 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:54.100441 31307 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/master-0-root/instance:
uuid: "4b262b9bc29e4c1dbc97cb9eda3a9463"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-gp6n"
I20260812 06:17:54.103874 31307 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:54.105922 31322 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:54.107079 31307 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:54.107223 31307 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/master-0-root
uuid: "4b262b9bc29e4c1dbc97cb9eda3a9463"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-gp6n"
I20260812 06:17:54.107331 31307 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:54.142736 31307 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:54.143429 31307 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:17:54.143615 31307 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:54.151342 31307 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.254:35253
I20260812 06:17:54.151347 31388 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.254:35253 every 8 connection(s)
I20260812 06:17:54.153501 31389 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:54.158797 31389 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463: Bootstrap starting.
I20260812 06:17:54.161003 31389 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:54.161805 31389 log.cc:826] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:54.163424 31389 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463: No bootstrap required, opened a new log
I20260812 06:17:54.166009 31389 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b262b9bc29e4c1dbc97cb9eda3a9463" member_type: VOTER }
I20260812 06:17:54.166162 31389 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:54.166209 31389 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4b262b9bc29e4c1dbc97cb9eda3a9463, State: Initialized, Role: FOLLOWER
I20260812 06:17:54.166766 31389 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [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: "4b262b9bc29e4c1dbc97cb9eda3a9463" member_type: VOTER }
I20260812 06:17:54.166905 31389 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:54.166952 31389 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:54.167032 31389 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:54.167711 31389 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b262b9bc29e4c1dbc97cb9eda3a9463" member_type: VOTER }
I20260812 06:17:54.168130 31389 leader_election.cc:304] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [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: 4b262b9bc29e4c1dbc97cb9eda3a9463; no voters: 
I20260812 06:17:54.168386 31389 leader_election.cc:290] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:54.168531 31392 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:54.168771 31392 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 1 LEADER]: Becoming Leader. State: Replica: 4b262b9bc29e4c1dbc97cb9eda3a9463, State: Running, Role: LEADER
I20260812 06:17:54.169163 31392 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [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: "4b262b9bc29e4c1dbc97cb9eda3a9463" member_type: VOTER }
I20260812 06:17:54.169387 31389 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:54.171170 31394 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4b262b9bc29e4c1dbc97cb9eda3a9463. Latest consensus state: current_term: 1 leader_uuid: "4b262b9bc29e4c1dbc97cb9eda3a9463" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b262b9bc29e4c1dbc97cb9eda3a9463" member_type: VOTER } }
I20260812 06:17:54.171144 31393 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4b262b9bc29e4c1dbc97cb9eda3a9463" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b262b9bc29e4c1dbc97cb9eda3a9463" member_type: VOTER } }
I20260812 06:17:54.171312 31393 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:54.171312 31394 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:54.171641 31307 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:54.174125 31410 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:54.174213 31410 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:54.174273 31409 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:54.175009 31409 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:54.179394 31409 catalog_manager.cc:1383] Generated new cluster ID: 9c60d064369b4c95bdb4605f8598ce06
I20260812 06:17:54.179456 31409 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:54.199165 31409 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:54.200006 31409 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:54.206115 31409 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463: Generated new TSK 0
I20260812 06:17:54.206739 31409 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:54.236462 31307 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:54.239142 31417 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:54.239190 31416 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:17:54.239190 31419 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:54.239676 31307 server_base.cc:1061] running on GCE node
I20260812 06:17:54.239846 31307 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:54.239893 31307 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:54.239916 31307 hybrid_clock.cc:648] HybridClock initialized: now 1786515474239916 us; error 0 us; skew 500 ppm
I20260812 06:17:54.240813 31307 webserver.cc:533] Webserver started at http://127.30.146.193:35445/ using document root <none> and password file <none>
I20260812 06:17:54.240983 31307 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:54.241055 31307 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:54.241132 31307 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:54.241580 31307 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/instance:
uuid: "36b19ebae0fb4571a564832156525783"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-gp6n"
I20260812 06:17:54.243538 31307 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:54.244688 31425 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:54.244959 31307 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:54.245047 31307 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root
uuid: "36b19ebae0fb4571a564832156525783"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-gp6n"
I20260812 06:17:54.245127 31307 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:54.259176 31307 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:54.259603 31307 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:54.260030 31307 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:54.260880 31307 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:54.260946 31307 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:54.261018 31307 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:54.261055 31307 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:54.267699 31307 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.193:37871
I20260812 06:17:54.267766 31500 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.193:37871 every 8 connection(s)
I20260812 06:17:54.278239 31501 heartbeater.cc:344] Connected to a master server at 127.30.146.254:35253
I20260812 06:17:54.278517 31501 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:54.279016 31501 heartbeater.cc:507] Master 127.30.146.254:35253 requested a full tablet report, sending...
I20260812 06:17:54.280412 31345 ts_manager.cc:194] Registered new tserver with Master: 36b19ebae0fb4571a564832156525783 (127.30.146.193:37871)
I20260812 06:17:54.280696 31307 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012369803s
I20260812 06:17:54.281994 31345 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58552
I20260812 06:17:54.289861 31345 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58554:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:54.303682 31456 tablet_service.cc:1511] Processing CreateTablet for tablet 06695cc326914efc9762bf0d4daa6a79 (DEFAULT_TABLE table=heavy-update-compaction-test [id=545b748d70c84bf68235f655bc969959]), partition=
I20260812 06:17:54.304107 31456 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 06695cc326914efc9762bf0d4daa6a79. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:54.306149 31516 tablet_bootstrap.cc:492] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Bootstrap starting.
I20260812 06:17:54.307221 31516 tablet_bootstrap.cc:654] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:54.308295 31516 tablet_bootstrap.cc:492] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: No bootstrap required, opened a new log
I20260812 06:17:54.308377 31516 ts_tablet_manager.cc:1403] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:54.308885 31516 raft_consensus.cc:359] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "36b19ebae0fb4571a564832156525783" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 37871 } }
I20260812 06:17:54.308983 31516 raft_consensus.cc:385] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:54.309015 31516 raft_consensus.cc:740] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 36b19ebae0fb4571a564832156525783, State: Initialized, Role: FOLLOWER
I20260812 06:17:54.309195 31516 consensus_queue.cc:260] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [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: "36b19ebae0fb4571a564832156525783" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 37871 } }
I20260812 06:17:54.309269 31516 raft_consensus.cc:399] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:54.309336 31516 raft_consensus.cc:493] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:54.309394 31516 raft_consensus.cc:3060] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:54.310228 31516 raft_consensus.cc:515] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "36b19ebae0fb4571a564832156525783" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 37871 } }
I20260812 06:17:54.310374 31516 leader_election.cc:304] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [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: 36b19ebae0fb4571a564832156525783; no voters: 
I20260812 06:17:54.310628 31516 leader_election.cc:290] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:54.310725 31518 raft_consensus.cc:2804] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:54.310930 31518 raft_consensus.cc:697] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 1 LEADER]: Becoming Leader. State: Replica: 36b19ebae0fb4571a564832156525783, State: Running, Role: LEADER
I20260812 06:17:54.311082 31516 ts_tablet_manager.cc:1434] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:54.311208 31518 consensus_queue.cc:237] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [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: "36b19ebae0fb4571a564832156525783" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 37871 } }
I20260812 06:17:54.311443 31501 heartbeater.cc:499] Master 127.30.146.254:35253 was elected leader, sending a full tablet report...
I20260812 06:17:54.313843 31345 catalog_manager.cc:5719] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 reported cstate change: term changed from 0 to 1, leader changed from <none> to 36b19ebae0fb4571a564832156525783 (127.30.146.193). New cstate: current_term: 1 leader_uuid: "36b19ebae0fb4571a564832156525783" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "36b19ebae0fb4571a564832156525783" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 37871 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:54.378180 31307 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.024s	sys 0.003s
I20260812 06:17:54.518805 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushMRSOp(06695cc326914efc9762bf0d4daa6a79): perf score=19.054940
I20260812 06:17:54.680986 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushMRSOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.162s	user 0.128s	sys 0.028s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":306,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1009,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41765,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":136,"threads_started":1,"update_count":1500}
I20260812 06:17:54.682011 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling LogGCOp(06695cc326914efc9762bf0d4daa6a79): free 20743880 bytes of WAL
I20260812 06:17:54.682297 31430 log_reader.cc:385] T 06695cc326914efc9762bf0d4daa6a79: removed 2 log segments from log reader
I20260812 06:17:54.682368 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000001 (ops 1-6)
I20260812 06:17:54.682452 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000002 (ops 7-11)
I20260812 06:17:54.686650 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: LogGCOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:54.686944 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling UndoDeltaBlockGCOp(06695cc326914efc9762bf0d4daa6a79): 16411393 bytes on disk
I20260812 06:17:54.687469 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: UndoDeltaBlockGCOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:54.687820 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:54.703913 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.704404 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:54.832602 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.128s	user 0.094s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":983,"lbm_read_time_us":7172,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22375,"lbm_writes_lt_1ms":443,"mutex_wait_us":101,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":321,"threads_started":5,"update_count":2000}
I20260812 06:17:54.833258 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:54.868888 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.035s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14821,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:54.869550 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:54.973224 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.103s	user 0.075s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":322,"lbm_read_time_us":5679,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18459,"lbm_writes_lt_1ms":343,"mutex_wait_us":43,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":1500}
I20260812 06:17:54.973928 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:55.019088 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.045s	user 0.016s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17649,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.019637 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:55.145983 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.126s	user 0.089s	sys 0.036s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":624,"lbm_read_time_us":7961,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20637,"lbm_writes_lt_1ms":343,"mutex_wait_us":321,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":1500}
I20260812 06:17:55.146579 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:55.185158 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.038s	user 0.029s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16547,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.185683 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:55.201754 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.202298 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:55.332015 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.130s	user 0.106s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":9454,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23306,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":60032,"update_count":2000}
I20260812 06:17:55.332573 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:55.377426 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.045s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12307555,"delete_count":0,"lbm_write_time_us":17189,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.377996 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:55.393343 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.393956 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:55.513078 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.119s	user 0.091s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672342,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":814,"lbm_read_time_us":8724,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23846,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.513847 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:55.560094 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.046s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15148,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.560614 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:55.570812 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.571285 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:55.711540 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.140s	user 0.096s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":437,"lbm_read_time_us":10320,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23046,"lbm_writes_lt_1ms":443,"mutex_wait_us":93,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2000}
I20260812 06:17:55.712175 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:55.753006 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.041s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16980,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.753469 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:55.763993 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.764621 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:55.889137 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.124s	user 0.089s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":8966,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25983,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:17:55.889938 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:55.928768 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.039s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15193,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.929261 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:55.944324 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.944959 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushMRSOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:55.977442 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushMRSOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1445,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1705,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:55.978191 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling LogGCOp(06695cc326914efc9762bf0d4daa6a79): free 124257242 bytes of WAL
I20260812 06:17:55.978466 31430 log_reader.cc:385] T 06695cc326914efc9762bf0d4daa6a79: removed 12 log segments from log reader
I20260812 06:17:55.978509 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000003 (ops 12-16)
I20260812 06:17:55.978538 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000004 (ops 17-21)
I20260812 06:17:55.978592 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000005 (ops 22-26)
I20260812 06:17:55.978632 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000006 (ops 27-31)
I20260812 06:17:55.978668 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000007 (ops 32-36)
I20260812 06:17:55.978708 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000008 (ops 37-41)
I20260812 06:17:55.978745 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000009 (ops 42-46)
I20260812 06:17:55.978785 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000010 (ops 47-50)
I20260812 06:17:55.978821 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000011 (ops 51-55)
I20260812 06:17:55.978861 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000012 (ops 56-60)
I20260812 06:17:55.978899 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000013 (ops 61-65)
I20260812 06:17:55.978936 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000014 (ops 66-70)
I20260812 06:17:56.005089 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: LogGCOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:56.005594 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling UndoDeltaBlockGCOp(06695cc326914efc9762bf0d4daa6a79): 473 bytes on disk
I20260812 06:17:56.006201 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: UndoDeltaBlockGCOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:56.006717 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=5.165500
I20260812 06:17:56.022883 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.016s	user 0.008s	sys 0.007s Metrics: {"bytes_written":6441038,"delete_count":0,"lbm_write_time_us":6662,"lbm_writes_lt_1ms":160,"reinsert_count":0,"update_count":785}
I20260812 06:17:56.023340 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:56.031826 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.008s	user 0.002s	sys 0.004s Metrics: {"bytes_written":1764227,"delete_count":0,"lbm_write_time_us":2805,"lbm_writes_lt_1ms":46,"reinsert_count":0,"update_count":215}
I20260812 06:17:56.032271 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:56.209165 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.177s	user 0.133s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877281,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":551,"lbm_read_time_us":11180,"lbm_reads_lt_1ms":666,"lbm_write_time_us":37119,"lbm_writes_lt_1ms":643,"mutex_wait_us":281,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:17:56.209827 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=14.095187
I20260812 06:17:56.265383 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.055s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21689,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.265837 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:56.277386 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.277822 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:56.435214 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.157s	user 0.106s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":637,"lbm_read_time_us":10273,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30919,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:56.435802 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=14.095187
I20260812 06:17:56.479074 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.043s	user 0.034s	sys 0.007s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18708,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.479674 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:56.490814 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4339,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.491420 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:56.637508 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.146s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":676,"lbm_read_time_us":10315,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27444,"lbm_writes_lt_1ms":543,"mutex_wait_us":309,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":102528,"update_count":2500}
I20260812 06:17:56.638208 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:56.671626 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.033s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14811,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:56.672605 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:56.693953 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.021s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6601,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.694590 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:56.854089 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.159s	user 0.106s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":684,"lbm_read_time_us":10744,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26105,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:56.854905 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=14.095187
I20260812 06:17:56.902837 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.048s	user 0.029s	sys 0.013s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18867,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.903350 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:56.923554 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.020s	user 0.009s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4314,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.924358 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:57.103324 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.179s	user 0.119s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":518,"lbm_read_time_us":10810,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28643,"lbm_writes_lt_1ms":543,"mutex_wait_us":262,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:57.103859 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=14.095187
I20260812 06:17:57.155814 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.052s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18572,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.156342 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:57.166366 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.166844 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:57.335691 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.169s	user 0.116s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":10826,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28633,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:17:57.336340 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:57.369958 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.033s	user 0.020s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14523,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.370690 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:57.380990 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3965,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.381461 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushMRSOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:57.413255 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushMRSOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":181,"dirs.run_wall_time_us":1781,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1603,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:57.414063 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling LogGCOp(06695cc326914efc9762bf0d4daa6a79): free 121006444 bytes of WAL
I20260812 06:17:57.414309 31430 log_reader.cc:385] T 06695cc326914efc9762bf0d4daa6a79: removed 12 log segments from log reader
I20260812 06:17:57.414373 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000015 (ops 71-75)
I20260812 06:17:57.414451 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000016 (ops 76-80)
I20260812 06:17:57.414500 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000017 (ops 81-85)
I20260812 06:17:57.414541 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000018 (ops 86-90)
I20260812 06:17:57.414578 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000019 (ops 91-95)
I20260812 06:17:57.414618 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000020 (ops 96-100)
I20260812 06:17:57.414659 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000021 (ops 101-105)
I20260812 06:17:57.414697 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000022 (ops 106-110)
I20260812 06:17:57.414737 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000023 (ops 111-115)
I20260812 06:17:57.414777 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000024 (ops 116-120)
I20260812 06:17:57.414816 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000025 (ops 121-124)
I20260812 06:17:57.414855 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000026 (ops 125-129)
I20260812 06:17:57.441716 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: LogGCOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:57.442293 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=3.181125
I20260812 06:17:57.454823 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4376,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:57.455291 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:57.479180 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5329,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:57.479820 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling UndoDeltaBlockGCOp(06695cc326914efc9762bf0d4daa6a79): 472 bytes on disk
I20260812 06:17:57.480476 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: UndoDeltaBlockGCOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:17:57.481036 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:57.675357 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.194s	user 0.125s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":170,"lbm_read_time_us":13480,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33892,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:17:57.676010 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=14.095187
I20260812 06:17:57.734892 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.059s	user 0.045s	sys 0.010s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20761,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.735435 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:57.746001 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.746459 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:57.914625 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.168s	user 0.111s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":12203,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29096,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:17:57.915374 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:57.950281 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.035s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15222,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.950845 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:57.966595 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.967113 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:58.095175 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.128s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":91,"lbm_read_time_us":9195,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25550,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:17:58.095700 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:58.128384 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.033s	user 0.014s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14521,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.128899 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:58.142985 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.014s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.143446 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:58.270931 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.127s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":8905,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24638,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:17:58.271595 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:58.303858 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14026,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.304370 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:58.317385 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.318076 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:58.438946 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.121s	user 0.089s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":707,"lbm_read_time_us":7356,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25295,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:58.439399 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:58.485975 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.046s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16958,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.486537 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:58.496752 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.497167 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:58.644798 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.147s	user 0.100s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":139,"lbm_read_time_us":10718,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24329,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":38400,"update_count":2000}
I20260812 06:17:58.645390 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:58.687984 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.042s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14748,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.688522 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:58.698941 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.699466 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:58.822022 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.122s	user 0.109s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":8647,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24936,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:17:58.822767 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:58.862263 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.039s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16607,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.862790 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:58.872807 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4036,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.873553 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushMRSOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:58.906073 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushMRSOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1375,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1364,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:58.906750 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling LogGCOp(06695cc326914efc9762bf0d4daa6a79): free 132571590 bytes of WAL
I20260812 06:17:58.906960 31430 log_reader.cc:385] T 06695cc326914efc9762bf0d4daa6a79: removed 13 log segments from log reader
I20260812 06:17:58.907015 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000027 (ops 130-134)
I20260812 06:17:58.907064 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000028 (ops 135-139)
I20260812 06:17:58.907114 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000029 (ops 140-144)
I20260812 06:17:58.907158 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000030 (ops 145-148)
I20260812 06:17:58.907194 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000031 (ops 149-153)
I20260812 06:17:58.907234 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000032 (ops 154-158)
I20260812 06:17:58.907271 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000033 (ops 159-163)
I20260812 06:17:58.907310 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000034 (ops 164-168)
I20260812 06:17:58.907348 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000035 (ops 169-173)
I20260812 06:17:58.907393 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000036 (ops 174-178)
I20260812 06:17:58.907433 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000037 (ops 179-183)
I20260812 06:17:58.907470 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000038 (ops 184-188)
I20260812 06:17:58.907508 31430 log.cc:1079] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/06695cc326914efc9762bf0d4daa6a79/wal-000000039 (ops 189-192)
I20260812 06:17:58.938678 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: LogGCOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:58.939110 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=3.181125
I20260812 06:17:58.952237 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":5005191,"delete_count":0,"lbm_write_time_us":5398,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:17:58.952644 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling UndoDeltaBlockGCOp(06695cc326914efc9762bf0d4daa6a79): 483 bytes on disk
I20260812 06:17:58.953003 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: UndoDeltaBlockGCOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.953471 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=2.188937
I20260812 06:17:58.964135 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":3425,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:17:58.964535 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:59.095953 31307 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.718s	user 1.760s	sys 0.131s
I20260812 06:17:59.134945 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.170s	user 0.137s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877315,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":11262,"lbm_reads_lt_1ms":670,"lbm_write_time_us":36797,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:59.135444 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79): perf score=10.126437
I20260812 06:17:59.165836 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: FlushDeltaMemStoresOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.030s	user 0.020s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12911,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.166333 31502 maintenance_manager.cc:419] P 36b19ebae0fb4571a564832156525783: Scheduling MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79): perf score=1.000000
I20260812 06:17:59.166721 31307 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.070s	user 0.004s	sys 0.000s
I20260812 06:17:59.167321 31307 tablet_server.cc:179] TabletServer@127.30.146.193:0 shutting down...
I20260812 06:17:59.255755 31430 maintenance_manager.cc:643] P 36b19ebae0fb4571a564832156525783: MajorDeltaCompactionOp(06695cc326914efc9762bf0d4daa6a79) complete. Timing: real 0.089s	user 0.066s	sys 0.023s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1078,"lbm_read_time_us":7087,"lbm_reads_lt_1ms":367,"lbm_write_time_us":16834,"lbm_writes_lt_1ms":343,"mutex_wait_us":380,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.256526 31307 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:59.257046 31307 tablet_replica.cc:333] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783: stopping tablet replica
I20260812 06:17:59.257247 31307 raft_consensus.cc:2243] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:59.257511 31307 raft_consensus.cc:2272] T 06695cc326914efc9762bf0d4daa6a79 P 36b19ebae0fb4571a564832156525783 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:59.273536 31307 tablet_server.cc:196] TabletServer@127.30.146.193:0 shutdown complete.
I20260812 06:17:59.287726 31307 master.cc:562] Master@127.30.146.254:35253 shutting down...
I20260812 06:17:59.291579 31307 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:59.291756 31307 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:59.291848 31307 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4b262b9bc29e4c1dbc97cb9eda3a9463: stopping tablet replica
I20260812 06:17:59.303967 31307 master.cc:584] Master@127.30.146.254:35253 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5306 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:59.405799 31307 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.146.254:34205
I20260812 06:17:59.406250 31307 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:59.408679 31548 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.408679 31545 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.408792 31544 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:59.408928 31307 server_base.cc:1061] running on GCE node
I20260812 06:17:59.409113 31307 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:59.409173 31307 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:59.409206 31307 hybrid_clock.cc:648] HybridClock initialized: now 1786515479409206 us; error 0 us; skew 500 ppm
I20260812 06:17:59.410125 31307 webserver.cc:533] Webserver started at http://127.30.146.254:38271/ using document root <none> and password file <none>
I20260812 06:17:59.410300 31307 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:59.410369 31307 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:59.410470 31307 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:59.410956 31307 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/master-0-root/instance:
uuid: "68a6f91de8d3410a872b834c1e7a2787"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-gp6n"
I20260812 06:17:59.412546 31307 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:59.413653 31556 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.413915 31307 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:59.414005 31307 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/master-0-root
uuid: "68a6f91de8d3410a872b834c1e7a2787"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-gp6n"
I20260812 06:17:59.414089 31307 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:59.437497 31307 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:59.437913 31307 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:59.442304 31307 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.254:34205
I20260812 06:17:59.443140 31618 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.254:34205 every 8 connection(s)
I20260812 06:17:59.443634 31619 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:59.445438 31619 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787: Bootstrap starting.
I20260812 06:17:59.446203 31619 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:59.447268 31619 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787: No bootstrap required, opened a new log
I20260812 06:17:59.447685 31619 raft_consensus.cc:359] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68a6f91de8d3410a872b834c1e7a2787" member_type: VOTER }
I20260812 06:17:59.447772 31619 raft_consensus.cc:385] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:59.447793 31619 raft_consensus.cc:740] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 68a6f91de8d3410a872b834c1e7a2787, State: Initialized, Role: FOLLOWER
I20260812 06:17:59.447981 31619 consensus_queue.cc:260] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [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: "68a6f91de8d3410a872b834c1e7a2787" member_type: VOTER }
I20260812 06:17:59.448055 31619 raft_consensus.cc:399] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:59.448112 31619 raft_consensus.cc:493] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:59.448173 31619 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:59.448853 31619 raft_consensus.cc:515] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68a6f91de8d3410a872b834c1e7a2787" member_type: VOTER }
I20260812 06:17:59.449003 31619 leader_election.cc:304] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [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: 68a6f91de8d3410a872b834c1e7a2787; no voters: 
I20260812 06:17:59.449204 31619 leader_election.cc:290] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:59.449301 31622 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:59.449591 31622 raft_consensus.cc:697] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 1 LEADER]: Becoming Leader. State: Replica: 68a6f91de8d3410a872b834c1e7a2787, State: Running, Role: LEADER
I20260812 06:17:59.449672 31619 sys_catalog.cc:565] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:59.449728 31622 consensus_queue.cc:237] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [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: "68a6f91de8d3410a872b834c1e7a2787" member_type: VOTER }
I20260812 06:17:59.450249 31624 sys_catalog.cc:455] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 68a6f91de8d3410a872b834c1e7a2787. Latest consensus state: current_term: 1 leader_uuid: "68a6f91de8d3410a872b834c1e7a2787" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68a6f91de8d3410a872b834c1e7a2787" member_type: VOTER } }
I20260812 06:17:59.450227 31623 sys_catalog.cc:455] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "68a6f91de8d3410a872b834c1e7a2787" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "68a6f91de8d3410a872b834c1e7a2787" member_type: VOTER } }
I20260812 06:17:59.450359 31624 sys_catalog.cc:458] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:59.450378 31623 sys_catalog.cc:458] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:59.450991 31633 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:59.451851 31633 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:59.452073 31307 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:59.453611 31633 catalog_manager.cc:1383] Generated new cluster ID: eee2bd7693b84b6ba48e6cf3c6d47d01
I20260812 06:17:59.453667 31633 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:59.460363 31633 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:59.460852 31633 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:59.465417 31633 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787: Generated new TSK 0
I20260812 06:17:59.465559 31633 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:59.468077 31307 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:59.469962 31307 server_base.cc:1061] running on GCE node
W20260812 06:17:59.470052 31648 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.470050 31650 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.470084 31647 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:59.470453 31307 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:59.470505 31307 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:59.470522 31307 hybrid_clock.cc:648] HybridClock initialized: now 1786515479470522 us; error 0 us; skew 500 ppm
I20260812 06:17:59.471503 31307 webserver.cc:533] Webserver started at http://127.30.146.193:36317/ using document root <none> and password file <none>
I20260812 06:17:59.471678 31307 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:59.471743 31307 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:59.471833 31307 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:59.472221 31307 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/instance:
uuid: "971ffdd000004a38b8e4d32c762030c1"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-gp6n"
I20260812 06:17:59.473783 31307 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:59.474949 31655 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.475199 31307 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:17:59.475265 31307 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root
uuid: "971ffdd000004a38b8e4d32c762030c1"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-gp6n"
I20260812 06:17:59.475394 31307 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:59.483949 31307 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:59.484351 31307 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:59.484663 31307 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:59.485146 31307 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:59.485208 31307 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.485266 31307 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:59.485316 31307 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.489981 31307 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.193:36159
I20260812 06:17:59.490723 31737 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.193:36159 every 8 connection(s)
I20260812 06:17:59.501189 31738 heartbeater.cc:344] Connected to a master server at 127.30.146.254:34205
I20260812 06:17:59.501327 31738 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:59.501582 31738 heartbeater.cc:507] Master 127.30.146.254:34205 requested a full tablet report, sending...
I20260812 06:17:59.502312 31576 ts_manager.cc:194] Registered new tserver with Master: 971ffdd000004a38b8e4d32c762030c1 (127.30.146.193:36159)
I20260812 06:17:59.503068 31307 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012202426s
I20260812 06:17:59.503083 31576 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51660
I20260812 06:17:59.510324 31576 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51670:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:59.519335 31690 tablet_service.cc:1511] Processing CreateTablet for tablet 866e7e917cf2401593dc814bf5715a56 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d184233dc0294c2b936d2c9616f3a8ea]), partition=
I20260812 06:17:59.519634 31690 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 866e7e917cf2401593dc814bf5715a56. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:59.521759 31752 tablet_bootstrap.cc:492] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Bootstrap starting.
I20260812 06:17:59.522693 31752 tablet_bootstrap.cc:654] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:59.523795 31752 tablet_bootstrap.cc:492] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: No bootstrap required, opened a new log
I20260812 06:17:59.523901 31752 ts_tablet_manager.cc:1403] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:59.524408 31752 raft_consensus.cc:359] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "971ffdd000004a38b8e4d32c762030c1" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 36159 } }
I20260812 06:17:59.524530 31752 raft_consensus.cc:385] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:59.524569 31752 raft_consensus.cc:740] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 971ffdd000004a38b8e4d32c762030c1, State: Initialized, Role: FOLLOWER
I20260812 06:17:59.524708 31752 consensus_queue.cc:260] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [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: "971ffdd000004a38b8e4d32c762030c1" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 36159 } }
I20260812 06:17:59.524806 31752 raft_consensus.cc:399] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:59.524849 31752 raft_consensus.cc:493] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:59.524906 31752 raft_consensus.cc:3060] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:59.525632 31752 raft_consensus.cc:515] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "971ffdd000004a38b8e4d32c762030c1" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 36159 } }
I20260812 06:17:59.525744 31752 leader_election.cc:304] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [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: 971ffdd000004a38b8e4d32c762030c1; no voters: 
I20260812 06:17:59.525910 31752 leader_election.cc:290] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:59.526115 31754 raft_consensus.cc:2804] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:59.526211 31752 ts_tablet_manager.cc:1434] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:59.526242 31738 heartbeater.cc:499] Master 127.30.146.254:34205 was elected leader, sending a full tablet report...
I20260812 06:17:59.526260 31754 raft_consensus.cc:697] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 1 LEADER]: Becoming Leader. State: Replica: 971ffdd000004a38b8e4d32c762030c1, State: Running, Role: LEADER
I20260812 06:17:59.526464 31754 consensus_queue.cc:237] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [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: "971ffdd000004a38b8e4d32c762030c1" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 36159 } }
I20260812 06:17:59.528071 31576 catalog_manager.cc:5719] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 reported cstate change: term changed from 0 to 1, leader changed from <none> to 971ffdd000004a38b8e4d32c762030c1 (127.30.146.193). New cstate: current_term: 1 leader_uuid: "971ffdd000004a38b8e4d32c762030c1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "971ffdd000004a38b8e4d32c762030c1" member_type: VOTER last_known_addr { host: "127.30.146.193" port: 36159 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:59.586427 31307 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.014s	sys 0.008s
I20260812 06:17:59.741415 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushMRSOp(866e7e917cf2401593dc814bf5715a56): perf score=19.054940
I20260812 06:17:59.891645 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushMRSOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.150s	user 0.109s	sys 0.039s Metrics: {"bytes_written":13579241,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":963,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39696,"lbm_writes_lt_1ms":788,"mutex_wait_us":206,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1655}
I20260812 06:17:59.892485 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling LogGCOp(866e7e917cf2401593dc814bf5715a56): free 20743880 bytes of WAL
I20260812 06:17:59.892728 31664 log_reader.cc:385] T 866e7e917cf2401593dc814bf5715a56: removed 2 log segments from log reader
I20260812 06:17:59.892797 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000001 (ops 1-6)
I20260812 06:17:59.892844 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000002 (ops 7-11)
I20260812 06:17:59.898067 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: LogGCOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:59.898524 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:17:59.913714 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.015s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3241135,"delete_count":0,"lbm_write_time_us":3188,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:17:59.914129 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling UndoDeltaBlockGCOp(866e7e917cf2401593dc814bf5715a56): 16411396 bytes on disk
I20260812 06:17:59.917896 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: UndoDeltaBlockGCOp(866e7e917cf2401593dc814bf5715a56) 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:17:59.918308 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:17:59.928647 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.010s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3850,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.929276 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:00.140834 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.211s	user 0.144s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":892,"lbm_read_time_us":13812,"lbm_reads_lt_1ms":569,"lbm_write_time_us":34687,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"thread_start_us":334,"threads_started":5,"update_count":2500}
I20260812 06:18:00.141511 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:00.195133 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.053s	user 0.042s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21182,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.195637 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:00.216074 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.020s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.216662 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:00.404451 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.188s	user 0.127s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":14532,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28459,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:18:00.405135 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:00.461968 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.057s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25602,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.462487 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:00.474812 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.475325 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:00.673861 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.198s	user 0.139s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":144,"lbm_read_time_us":13003,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33329,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:00.674659 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:00.721560 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.047s	user 0.026s	sys 0.018s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20663,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.722047 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:00.737643 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.738201 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:00.900038 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.162s	user 0.140s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":207,"lbm_read_time_us":11028,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32370,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:18:00.900573 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=11.118625
I20260812 06:18:00.941368 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.041s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17657,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:00.941958 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:00.953536 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.953954 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:01.067840 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.114s	user 0.098s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":728,"lbm_read_time_us":7540,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21826,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.068615 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=10.126437
I20260812 06:18:01.116547 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.048s	user 0.016s	sys 0.029s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22664,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.117046 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:01.127337 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.128069 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushMRSOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:01.159603 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushMRSOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1439,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1930,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:01.160158 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling LogGCOp(866e7e917cf2401593dc814bf5715a56): free 108535459 bytes of WAL
I20260812 06:18:01.160377 31664 log_reader.cc:385] T 866e7e917cf2401593dc814bf5715a56: removed 11 log segments from log reader
I20260812 06:18:01.160421 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000003 (ops 12-16)
I20260812 06:18:01.160449 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000004 (ops 17-21)
I20260812 06:18:01.160506 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000005 (ops 22-26)
I20260812 06:18:01.160542 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000006 (ops 27-30)
I20260812 06:18:01.160581 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000007 (ops 31-35)
I20260812 06:18:01.160599 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000008 (ops 36-40)
I20260812 06:18:01.160651 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000009 (ops 41-45)
I20260812 06:18:01.160691 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000010 (ops 46-50)
I20260812 06:18:01.160729 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000011 (ops 51-54)
I20260812 06:18:01.160765 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000012 (ops 55-59)
I20260812 06:18:01.160804 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000013 (ops 60-64)
I20260812 06:18:01.181975 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: LogGCOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.022s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:01.182377 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:01.201457 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.019s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.201872 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling LogGCOp(866e7e917cf2401593dc814bf5715a56): free 11564875 bytes of WAL
I20260812 06:18:01.202082 31664 log_reader.cc:385] T 866e7e917cf2401593dc814bf5715a56: removed 1 log segments from log reader
I20260812 06:18:01.202127 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000014 (ops 65-68)
I20260812 06:18:01.204365 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: LogGCOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:01.204716 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling UndoDeltaBlockGCOp(866e7e917cf2401593dc814bf5715a56): 448 bytes on disk
I20260812 06:18:01.205101 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: UndoDeltaBlockGCOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.205529 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:01.217176 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.217624 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:01.397696 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.180s	user 0.128s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":591,"lbm_read_time_us":13310,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35196,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":62336,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:18:01.400660 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:01.445466 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.045s	user 0.032s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19227,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.446081 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:01.461185 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.461796 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:01.620679 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.159s	user 0.110s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":742,"lbm_read_time_us":11739,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29605,"lbm_writes_lt_1ms":543,"mutex_wait_us":344,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:18:01.623443 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=11.118625
I20260812 06:18:01.659089 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.035s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15971,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:01.659559 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:01.671823 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4613,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.672370 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:01.805209 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.132s	user 0.095s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":96,"lbm_read_time_us":9276,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22438,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:18:01.805980 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=10.126437
I20260812 06:18:01.841761 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.036s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15022,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.842525 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:01.858309 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5592,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.858916 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:01.981441 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.122s	user 0.079s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1419,"lbm_read_time_us":7541,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22413,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:01.982161 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=11.118625
I20260812 06:18:02.012668 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.030s	user 0.012s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13395,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.013151 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:02.032262 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.019s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5752,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.032791 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:02.154558 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.122s	user 0.091s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":7554,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23801,"lbm_writes_lt_1ms":443,"mutex_wait_us":312,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.155202 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=11.118625
I20260812 06:18:02.199496 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":19561,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.199994 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:02.211483 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.212020 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:02.349359 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.137s	user 0.111s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":985,"lbm_read_time_us":10037,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26386,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:02.349977 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=11.118625
I20260812 06:18:02.396013 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.046s	user 0.021s	sys 0.023s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15051,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.396603 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:02.411288 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.014s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.411810 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:02.585258 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.173s	user 0.124s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":10507,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26678,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:18:02.585949 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:02.632092 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.046s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20431,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.632596 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:02.644086 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.644646 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushMRSOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:02.680970 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushMRSOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.036s	user 0.023s	sys 0.011s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1331,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1801,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:02.681632 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling LogGCOp(866e7e917cf2401593dc814bf5715a56): free 121006381 bytes of WAL
I20260812 06:18:02.681861 31664 log_reader.cc:385] T 866e7e917cf2401593dc814bf5715a56: removed 12 log segments from log reader
I20260812 06:18:02.681906 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000015 (ops 69-73)
I20260812 06:18:02.681936 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000016 (ops 74-78)
I20260812 06:18:02.681998 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000017 (ops 79-83)
I20260812 06:18:02.682045 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000018 (ops 84-88)
I20260812 06:18:02.682081 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000019 (ops 89-93)
I20260812 06:18:02.682139 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000020 (ops 94-98)
I20260812 06:18:02.682168 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000021 (ops 99-103)
I20260812 06:18:02.682201 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000022 (ops 104-108)
I20260812 06:18:02.682238 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000023 (ops 109-113)
I20260812 06:18:02.682276 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000024 (ops 114-118)
I20260812 06:18:02.682318 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000025 (ops 119-122)
I20260812 06:18:02.682356 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000026 (ops 123-127)
I20260812 06:18:02.708880 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: LogGCOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.027s	user 0.006s	sys 0.019s Metrics: {}
I20260812 06:18:02.709358 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling UndoDeltaBlockGCOp(866e7e917cf2401593dc814bf5715a56): 492 bytes on disk
I20260812 06:18:02.709836 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: UndoDeltaBlockGCOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.710347 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=3.181125
I20260812 06:18:02.724053 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4923,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:02.724516 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:02.920819 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.196s	user 0.138s	sys 0.052s Metrics: {"cfile_cache_miss":643,"cfile_cache_miss_bytes":29287464,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":260,"lbm_read_time_us":12414,"lbm_reads_lt_1ms":675,"lbm_write_time_us":33396,"lbm_writes_lt_1ms":653,"mutex_wait_us":29,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":7808,"thread_start_us":74,"threads_started":1,"update_count":3050}
I20260812 06:18:02.922008 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=18.063937
I20260812 06:18:02.989089 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.066s	user 0.013s	sys 0.051s Metrics: {"bytes_written":20102074,"delete_count":0,"lbm_write_time_us":26003,"lbm_writes_lt_1ms":493,"reinsert_count":0,"update_count":2450}
I20260812 06:18:02.989638 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:03.000042 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.000455 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:03.189472 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.189s	user 0.112s	sys 0.076s Metrics: {"cfile_cache_miss":622,"cfile_cache_miss_bytes":28466861,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":14271,"lbm_reads_lt_1ms":662,"lbm_write_time_us":33872,"lbm_writes_lt_1ms":633,"mutex_wait_us":41,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2950}
I20260812 06:18:03.190083 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:03.249608 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.059s	user 0.043s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20595,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.250216 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:03.267858 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.268548 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:03.429244 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.160s	user 0.085s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":930,"lbm_read_time_us":11493,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26089,"lbm_writes_lt_1ms":543,"mutex_wait_us":264,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":136192,"update_count":2500}
I20260812 06:18:03.429886 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:03.487246 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.057s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18843,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.487762 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:03.498066 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.498526 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:03.679811 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.181s	user 0.110s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":140,"lbm_read_time_us":13267,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30060,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:03.680502 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:03.730751 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.050s	user 0.039s	sys 0.005s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19703,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.731308 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:03.756556 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.025s	user 0.004s	sys 0.019s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.757295 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:03.954416 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.197s	user 0.149s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":13357,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34163,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:03.955034 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:04.007258 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.052s	user 0.016s	sys 0.027s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19626,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.007767 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:04.018775 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.019258 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:04.199407 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.180s	user 0.121s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1367,"lbm_read_time_us":10682,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26499,"lbm_writes_lt_1ms":543,"mutex_wait_us":331,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:18:04.200131 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=14.095187
I20260812 06:18:04.255328 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.055s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23679,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.255815 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=2.188937
I20260812 06:18:04.267042 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.267777 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushMRSOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:04.300144 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushMRSOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1486,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1626,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:04.300830 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling LogGCOp(866e7e917cf2401593dc814bf5715a56): free 133477753 bytes of WAL
I20260812 06:18:04.301065 31664 log_reader.cc:385] T 866e7e917cf2401593dc814bf5715a56: removed 13 log segments from log reader
I20260812 06:18:04.301110 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000027 (ops 128-132)
I20260812 06:18:04.301138 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000028 (ops 133-137)
I20260812 06:18:04.301199 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000029 (ops 138-142)
I20260812 06:18:04.301232 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000030 (ops 143-147)
I20260812 06:18:04.301265 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000031 (ops 148-152)
I20260812 06:18:04.301322 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000032 (ops 153-157)
I20260812 06:18:04.301363 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000033 (ops 158-162)
I20260812 06:18:04.301409 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000034 (ops 163-167)
I20260812 06:18:04.301448 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000035 (ops 168-172)
I20260812 06:18:04.301487 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000036 (ops 173-177)
I20260812 06:18:04.301525 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000037 (ops 178-182)
I20260812 06:18:04.301561 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000038 (ops 183-187)
I20260812 06:18:04.301600 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000039 (ops 188-192)
I20260812 06:18:04.334115 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: LogGCOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:04.334576 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=4.173312
I20260812 06:18:04.348263 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5784656,"delete_count":0,"lbm_write_time_us":5556,"lbm_writes_lt_1ms":144,"reinsert_count":0,"update_count":705}
I20260812 06:18:04.348690 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling LogGCOp(866e7e917cf2401593dc814bf5715a56): free 11564893 bytes of WAL
I20260812 06:18:04.348889 31664 log_reader.cc:385] T 866e7e917cf2401593dc814bf5715a56: removed 1 log segments from log reader
I20260812 06:18:04.348937 31664 log.cc:1079] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: Deleting log segment in path: /tmp/dist-test-taskSNViNj/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474075061-31307-0/minicluster-data/ts-0-root/wals/866e7e917cf2401593dc814bf5715a56/wal-000000040 (ops 193-196)
I20260812 06:18:04.351509 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: LogGCOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:04.351843 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling UndoDeltaBlockGCOp(866e7e917cf2401593dc814bf5715a56): 493 bytes on disk
I20260812 06:18:04.352242 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: UndoDeltaBlockGCOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.352711 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56): perf score=1.196750
I20260812 06:18:04.361691 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: FlushDeltaMemStoresOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.009s	user 0.000s	sys 0.005s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":2301,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:18:04.362099 31739 maintenance_manager.cc:419] P 971ffdd000004a38b8e4d32c762030c1: Scheduling MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56): perf score=1.000000
I20260812 06:18:04.436491 31307 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.850s	user 1.754s	sys 0.190s
I20260812 06:18:04.544534 31307 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.108s	user 0.001s	sys 0.000s
I20260812 06:18:04.545019 31307 tablet_server.cc:179] TabletServer@127.30.146.193:0 shutting down...
I20260812 06:18:04.574331 31664 maintenance_manager.cc:643] P 971ffdd000004a38b8e4d32c762030c1: MajorDeltaCompactionOp(866e7e917cf2401593dc814bf5715a56) complete. Timing: real 0.212s	user 0.156s	sys 0.056s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979713,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":861,"lbm_read_time_us":17514,"lbm_reads_lt_1ms":770,"lbm_write_time_us":33627,"lbm_writes_lt_1ms":743,"mutex_wait_us":344,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":25984,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:18:04.575040 31307 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:04.575383 31307 tablet_replica.cc:333] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1: stopping tablet replica
I20260812 06:18:04.575562 31307 raft_consensus.cc:2243] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:04.575755 31307 raft_consensus.cc:2272] T 866e7e917cf2401593dc814bf5715a56 P 971ffdd000004a38b8e4d32c762030c1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:04.580874 31307 tablet_server.cc:196] TabletServer@127.30.146.193:0 shutdown complete.
I20260812 06:18:04.635880 31307 master.cc:562] Master@127.30.146.254:34205 shutting down...
I20260812 06:18:04.639276 31307 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:04.639477 31307 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:04.639564 31307 tablet_replica.cc:333] T 00000000000000000000000000000000 P 68a6f91de8d3410a872b834c1e7a2787: stopping tablet replica
I20260812 06:18:04.652017 31307 master.cc:584] Master@127.30.146.254:34205 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5343 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10651 ms total)

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