[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:09.627526 29582 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.227.190:33991
I20260812 06:19:09.628572 29582 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:09.629204 29582 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:09.635869 29590 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:09.635864 29593 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:09.635927 29582 server_base.cc:1061] running on GCE node
W20260812 06:19:09.636132 29591 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:09.636653 29582 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:09.636781 29582 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:09.636829 29582 hybrid_clock.cc:648] HybridClock initialized: now 1786515549636827 us; error 0 us; skew 500 ppm
I20260812 06:19:09.638789 29582 webserver.cc:533] Webserver started at http://127.28.227.190:35697/ using document root <none> and password file <none>
I20260812 06:19:09.639392 29582 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:09.639479 29582 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:09.639755 29582 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:09.641566 29582 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/master-0-root/instance:
uuid: "2eb53e6ff21d4879b19f12f89806f154"
format_stamp: "Formatted at 2026-08-12 06:19:09 on dist-test-slave-njxd"
I20260812 06:19:09.645395 29582 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:09.647686 29601 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:09.648780 29582 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:09.648916 29582 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/master-0-root
uuid: "2eb53e6ff21d4879b19f12f89806f154"
format_stamp: "Formatted at 2026-08-12 06:19:09 on dist-test-slave-njxd"
I20260812 06:19:09.649021 29582 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:09.659152 29582 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:09.659838 29582 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:09.660028 29582 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:09.668201 29582 rpc_server.cc:307] RPC server started. Bound to: 127.28.227.190:33991
I20260812 06:19:09.668203 29668 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.227.190:33991 every 8 connection(s)
I20260812 06:19:09.670644 29669 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:09.676323 29669 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154: Bootstrap starting.
I20260812 06:19:09.678773 29669 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:09.679740 29669 log.cc:826] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:09.681522 29669 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154: No bootstrap required, opened a new log
I20260812 06:19:09.684402 29669 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2eb53e6ff21d4879b19f12f89806f154" member_type: VOTER }
I20260812 06:19:09.684579 29669 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:09.684623 29669 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2eb53e6ff21d4879b19f12f89806f154, State: Initialized, Role: FOLLOWER
I20260812 06:19:09.685256 29669 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [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: "2eb53e6ff21d4879b19f12f89806f154" member_type: VOTER }
I20260812 06:19:09.685429 29669 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:09.685515 29669 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:09.685719 29669 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:09.686599 29669 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2eb53e6ff21d4879b19f12f89806f154" member_type: VOTER }
I20260812 06:19:09.687098 29669 leader_election.cc:304] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [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: 2eb53e6ff21d4879b19f12f89806f154; no voters: 
I20260812 06:19:09.687464 29669 leader_election.cc:290] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:09.687621 29672 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:09.687893 29672 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 1 LEADER]: Becoming Leader. State: Replica: 2eb53e6ff21d4879b19f12f89806f154, State: Running, Role: LEADER
I20260812 06:19:09.688400 29672 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [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: "2eb53e6ff21d4879b19f12f89806f154" member_type: VOTER }
I20260812 06:19:09.688622 29669 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:09.690500 29673 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2eb53e6ff21d4879b19f12f89806f154" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2eb53e6ff21d4879b19f12f89806f154" member_type: VOTER } }
I20260812 06:19:09.690469 29674 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2eb53e6ff21d4879b19f12f89806f154. Latest consensus state: current_term: 1 leader_uuid: "2eb53e6ff21d4879b19f12f89806f154" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2eb53e6ff21d4879b19f12f89806f154" member_type: VOTER } }
I20260812 06:19:09.690618 29673 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:09.690618 29674 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:09.691148 29582 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:09.693351 29691 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:09.693434 29691 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:09.693554 29688 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:09.694350 29688 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:09.699841 29688 catalog_manager.cc:1383] Generated new cluster ID: a62b939aec4c46b38c1fd244066bc9ca
I20260812 06:19:09.699940 29688 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:09.712182 29688 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:09.713125 29688 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:09.718457 29688 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154: Generated new TSK 0
I20260812 06:19:09.719110 29688 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:09.723948 29582 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:09.726586 29698 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:09.726697 29699 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:09.726866 29582 server_base.cc:1061] running on GCE node
W20260812 06:19:09.726917 29701 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:09.727167 29582 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:09.727227 29582 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:09.727259 29582 hybrid_clock.cc:648] HybridClock initialized: now 1786515549727259 us; error 0 us; skew 500 ppm
I20260812 06:19:09.728271 29582 webserver.cc:533] Webserver started at http://127.28.227.129:45489/ using document root <none> and password file <none>
I20260812 06:19:09.728447 29582 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:09.728509 29582 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:09.728590 29582 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:09.729040 29582 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/instance:
uuid: "5a50fdce89cf4cefab54eb75abdef08d"
format_stamp: "Formatted at 2026-08-12 06:19:09 on dist-test-slave-njxd"
I20260812 06:19:09.730995 29582 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:09.732177 29706 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:09.732468 29582 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:09.732551 29582 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root
uuid: "5a50fdce89cf4cefab54eb75abdef08d"
format_stamp: "Formatted at 2026-08-12 06:19:09 on dist-test-slave-njxd"
I20260812 06:19:09.732630 29582 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:09.755808 29582 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:09.756378 29582 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:09.756943 29582 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:09.758038 29582 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:09.758111 29582 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:09.758172 29582 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:09.758203 29582 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:09.765089 29582 rpc_server.cc:307] RPC server started. Bound to: 127.28.227.129:35307
I20260812 06:19:09.765187 29784 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.227.129:35307 every 8 connection(s)
I20260812 06:19:09.779072 29785 heartbeater.cc:344] Connected to a master server at 127.28.227.190:33991
I20260812 06:19:09.779379 29785 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:09.779901 29785 heartbeater.cc:507] Master 127.28.227.190:33991 requested a full tablet report, sending...
I20260812 06:19:09.781493 29623 ts_manager.cc:194] Registered new tserver with Master: 5a50fdce89cf4cefab54eb75abdef08d (127.28.227.129:35307)
I20260812 06:19:09.781695 29582 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015775384s
I20260812 06:19:09.783156 29623 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41002
I20260812 06:19:09.792745 29623 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41006:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:09.808995 29745 tablet_service.cc:1511] Processing CreateTablet for tablet 253c0dcb00e04eec895e8516aea99eea (DEFAULT_TABLE table=heavy-update-compaction-test [id=941c4404073541cd90d1715b061d34bf]), partition=
I20260812 06:19:09.809490 29745 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 253c0dcb00e04eec895e8516aea99eea. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:09.812140 29798 tablet_bootstrap.cc:492] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Bootstrap starting.
I20260812 06:19:09.813184 29798 tablet_bootstrap.cc:654] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:09.814446 29798 tablet_bootstrap.cc:492] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: No bootstrap required, opened a new log
I20260812 06:19:09.814592 29798 ts_tablet_manager.cc:1403] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:09.815054 29798 raft_consensus.cc:359] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5a50fdce89cf4cefab54eb75abdef08d" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 35307 } }
I20260812 06:19:09.815186 29798 raft_consensus.cc:385] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:09.815255 29798 raft_consensus.cc:740] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5a50fdce89cf4cefab54eb75abdef08d, State: Initialized, Role: FOLLOWER
I20260812 06:19:09.815429 29798 consensus_queue.cc:260] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [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: "5a50fdce89cf4cefab54eb75abdef08d" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 35307 } }
I20260812 06:19:09.815574 29798 raft_consensus.cc:399] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:09.815665 29798 raft_consensus.cc:493] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:09.815727 29798 raft_consensus.cc:3060] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:09.816641 29798 raft_consensus.cc:515] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5a50fdce89cf4cefab54eb75abdef08d" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 35307 } }
I20260812 06:19:09.816834 29798 leader_election.cc:304] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [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: 5a50fdce89cf4cefab54eb75abdef08d; no voters: 
I20260812 06:19:09.817086 29798 leader_election.cc:290] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:09.817404 29800 raft_consensus.cc:2804] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:09.817471 29798 ts_tablet_manager.cc:1434] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:09.817780 29785 heartbeater.cc:499] Master 127.28.227.190:33991 was elected leader, sending a full tablet report...
I20260812 06:19:09.817778 29800 raft_consensus.cc:697] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 1 LEADER]: Becoming Leader. State: Replica: 5a50fdce89cf4cefab54eb75abdef08d, State: Running, Role: LEADER
I20260812 06:19:09.818040 29800 consensus_queue.cc:237] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [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: "5a50fdce89cf4cefab54eb75abdef08d" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 35307 } }
I20260812 06:19:09.821086 29623 catalog_manager.cc:5719] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d reported cstate change: term changed from 0 to 1, leader changed from <none> to 5a50fdce89cf4cefab54eb75abdef08d (127.28.227.129). New cstate: current_term: 1 leader_uuid: "5a50fdce89cf4cefab54eb75abdef08d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5a50fdce89cf4cefab54eb75abdef08d" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 35307 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:09.888861 29582 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.023s	sys 0.004s
I20260812 06:19:10.016363 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushMRSOp(253c0dcb00e04eec895e8516aea99eea): perf score=15.086190
I20260812 06:19:10.176985 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushMRSOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.160s	user 0.134s	sys 0.016s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":243,"delete_count":0,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":989,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41119,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":656,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":118,"threads_started":1,"update_count":1450}
I20260812 06:19:10.178115 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling LogGCOp(253c0dcb00e04eec895e8516aea99eea): free 20743880 bytes of WAL
I20260812 06:19:10.178447 29714 log_reader.cc:385] T 253c0dcb00e04eec895e8516aea99eea: removed 2 log segments from log reader
I20260812 06:19:10.178529 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000001 (ops 1-6)
I20260812 06:19:10.178637 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000002 (ops 7-11)
I20260812 06:19:10.183156 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: LogGCOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:10.183668 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling UndoDeltaBlockGCOp(253c0dcb00e04eec895e8516aea99eea): 12719216 bytes on disk
I20260812 06:19:10.184274 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: UndoDeltaBlockGCOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.184681 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:10.201828 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.017s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6518,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.202381 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:10.332979 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.130s	user 0.111s	sys 0.016s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":591,"lbm_read_time_us":7486,"lbm_reads_lt_1ms":454,"lbm_write_time_us":25476,"lbm_writes_lt_1ms":433,"mutex_wait_us":38,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":308,"threads_started":5,"update_count":1950}
I20260812 06:19:10.333599 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:10.383492 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.050s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16939,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.384020 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:10.395448 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.009s	sys 0.000s 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:19:10.396099 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:10.521723 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.125s	user 0.103s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":692,"lbm_read_time_us":7989,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26196,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:19:10.522343 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:10.564560 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.042s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15971,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.565187 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:10.576596 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4013,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.577234 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:10.706765 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.129s	user 0.101s	sys 0.028s 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":1391,"lbm_read_time_us":8854,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24320,"lbm_writes_lt_1ms":443,"mutex_wait_us":527,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2000}
I20260812 06:19:10.707547 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:10.749667 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.042s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14537,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.750268 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:10.761686 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4196,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.762159 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:10.909293 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.147s	user 0.102s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1003,"lbm_read_time_us":11725,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23433,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:19:10.909946 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:10.952207 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.042s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15410,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.952735 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:10.964658 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.965297 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:11.079953 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.114s	user 0.082s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":7775,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23131,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2000}
I20260812 06:19:11.080507 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:11.123561 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.043s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15615,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.124204 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:11.136408 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4514,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.136989 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:11.265082 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.128s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":149,"lbm_read_time_us":9169,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25597,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:19:11.265795 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:11.313266 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.047s	user 0.016s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17523,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.313938 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:11.324734 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.325218 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:11.469550 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.144s	user 0.104s	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":558,"lbm_read_time_us":10852,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24650,"lbm_writes_lt_1ms":443,"mutex_wait_us":98,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.470394 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:11.512362 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.042s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15307,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.512895 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:11.524355 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.525104 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushMRSOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:11.554368 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushMRSOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.029s	user 0.024s	sys 0.005s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1468,"drs_written":1,"lbm_read_time_us":119,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1960,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":768}
I20260812 06:19:11.555254 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling LogGCOp(253c0dcb00e04eec895e8516aea99eea): free 120553380 bytes of WAL
I20260812 06:19:11.555505 29714 log_reader.cc:385] T 253c0dcb00e04eec895e8516aea99eea: removed 12 log segments from log reader
I20260812 06:19:11.555553 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000003 (ops 12-16)
I20260812 06:19:11.555583 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000004 (ops 17-21)
I20260812 06:19:11.555645 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000005 (ops 22-26)
I20260812 06:19:11.555676 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000006 (ops 27-31)
I20260812 06:19:11.555716 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000007 (ops 32-36)
I20260812 06:19:11.555776 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000008 (ops 37-40)
I20260812 06:19:11.555814 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000009 (ops 41-45)
I20260812 06:19:11.555855 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000010 (ops 46-50)
I20260812 06:19:11.555891 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000011 (ops 51-54)
I20260812 06:19:11.555929 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000012 (ops 55-59)
I20260812 06:19:11.555967 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000013 (ops 60-64)
I20260812 06:19:11.556005 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000014 (ops 65-69)
I20260812 06:19:11.581463 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: LogGCOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:11.582052 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling UndoDeltaBlockGCOp(253c0dcb00e04eec895e8516aea99eea): 483 bytes on disk
I20260812 06:19:11.582595 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: UndoDeltaBlockGCOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:11.583190 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=3.181125
I20260812 06:19:11.605988 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.023s	user 0.005s	sys 0.018s Metrics: {"bytes_written":4718026,"delete_count":0,"lbm_write_time_us":5111,"lbm_writes_lt_1ms":118,"reinsert_count":0,"update_count":575}
I20260812 06:19:11.606678 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:11.616801 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":3675,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:19:11.617334 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:11.834143 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.217s	user 0.141s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":643,"lbm_read_time_us":15640,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36174,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:11.834748 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=14.095187
I20260812 06:19:11.910666 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.076s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22119,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.911268 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:11.923158 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.012s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.923655 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:12.118680 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.195s	user 0.127s	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":147,"lbm_read_time_us":13132,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36551,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:12.119333 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:12.157886 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.038s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17435,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.158448 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:12.174733 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.175246 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:12.309077 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.134s	user 0.116s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":10106,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25018,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:19:12.309808 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:12.354770 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.045s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15623,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.355336 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:12.366927 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4312,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.367576 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:12.496857 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.129s	user 0.089s	sys 0.040s 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":248,"lbm_read_time_us":9788,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25720,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":62720,"update_count":2000}
I20260812 06:19:12.497612 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:12.541038 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.043s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18732,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.541564 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:12.657503 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.116s	user 0.087s	sys 0.025s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":242,"lbm_read_time_us":6542,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22909,"lbm_writes_lt_1ms":343,"mutex_wait_us":26,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":1500}
I20260812 06:19:12.658083 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:12.706300 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.048s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16566,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.706802 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:12.718042 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4203,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.718708 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:12.865743 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.147s	user 0.105s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":693,"lbm_read_time_us":9413,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28642,"lbm_writes_lt_1ms":443,"mutex_wait_us":308,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:19:12.866303 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:12.904398 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.038s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14757,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.904975 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:13.019313 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.114s	user 0.078s	sys 0.035s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569745,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":335,"lbm_read_time_us":5858,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22419,"lbm_writes_lt_1ms":343,"mutex_wait_us":98,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:19:13.020231 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:13.059559 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.039s	user 0.016s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18251,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:13.060086 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushMRSOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:13.089752 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushMRSOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.029s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1471,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1483,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:13.090500 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling LogGCOp(253c0dcb00e04eec895e8516aea99eea): free 121006447 bytes of WAL
I20260812 06:19:13.090758 29714 log_reader.cc:385] T 253c0dcb00e04eec895e8516aea99eea: removed 12 log segments from log reader
I20260812 06:19:13.090804 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000015 (ops 70-74)
I20260812 06:19:13.090833 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000016 (ops 75-79)
I20260812 06:19:13.090898 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000017 (ops 80-84)
I20260812 06:19:13.090931 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000018 (ops 85-89)
I20260812 06:19:13.090966 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000019 (ops 90-94)
I20260812 06:19:13.091030 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000020 (ops 95-99)
I20260812 06:19:13.091112 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000021 (ops 100-104)
I20260812 06:19:13.091156 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000022 (ops 105-108)
I20260812 06:19:13.091176 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000023 (ops 109-113)
I20260812 06:19:13.091231 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000024 (ops 114-118)
I20260812 06:19:13.091272 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000025 (ops 119-123)
I20260812 06:19:13.091316 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000026 (ops 124-128)
I20260812 06:19:13.118870 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: LogGCOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:13.119270 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling UndoDeltaBlockGCOp(253c0dcb00e04eec895e8516aea99eea): 462 bytes on disk
I20260812 06:19:13.119786 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: UndoDeltaBlockGCOp(253c0dcb00e04eec895e8516aea99eea) 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:19:13.120465 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=5.165500
I20260812 06:19:13.138969 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.018s	user 0.017s	sys 0.000s Metrics: {"bytes_written":7220498,"delete_count":0,"lbm_write_time_us":7243,"lbm_writes_lt_1ms":179,"reinsert_count":0,"update_count":880}
I20260812 06:19:13.139761 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:13.293411 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.153s	user 0.129s	sys 0.024s Metrics: {"cfile_cache_miss":508,"cfile_cache_miss_bytes":23790112,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1342,"lbm_read_time_us":12266,"lbm_reads_lt_1ms":544,"lbm_write_time_us":27797,"lbm_writes_lt_1ms":519,"mutex_wait_us":311,"peak_mem_usage":60050292,"reinsert_count":0,"spinlock_wait_cycles":19584,"thread_start_us":88,"threads_started":1,"update_count":2380}
I20260812 06:19:13.294287 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=12.110812
I20260812 06:19:13.337121 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.043s	user 0.029s	sys 0.010s Metrics: {"bytes_written":13702314,"delete_count":0,"lbm_write_time_us":15443,"lbm_writes_lt_1ms":337,"reinsert_count":0,"update_count":1670}
I20260812 06:19:13.337762 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling LogGCOp(253c0dcb00e04eec895e8516aea99eea): free 11564891 bytes of WAL
I20260812 06:19:13.337984 29714 log_reader.cc:385] T 253c0dcb00e04eec895e8516aea99eea: removed 1 log segments from log reader
I20260812 06:19:13.338047 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000027 (ops 129-132)
I20260812 06:19:13.340468 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: LogGCOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:13.340848 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:13.367887 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.027s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6027,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:13.368467 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:13.383567 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5753,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.384131 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:13.564337 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.180s	user 0.118s	sys 0.059s Metrics: {"cfile_cache_miss":557,"cfile_cache_miss_bytes":25759378,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1024,"lbm_read_time_us":13500,"lbm_reads_lt_1ms":597,"lbm_write_time_us":32234,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":566,"mutex_wait_us":272,"peak_mem_usage":66181508,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2620}
I20260812 06:19:13.564906 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=14.095187
I20260812 06:19:13.619524 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.054s	user 0.039s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21256,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:19:13.620051 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:13.630941 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.631440 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:13.806780 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.175s	user 0.099s	sys 0.066s 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":234,"lbm_read_time_us":12824,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30108,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:13.807418 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=14.095187
I20260812 06:19:13.877429 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.070s	user 0.026s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24273,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:13.878120 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:13.889010 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4172,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.889489 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:14.057004 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.167s	user 0.124s	sys 0.042s 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":630,"lbm_read_time_us":12728,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30683,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:14.057687 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=11.118625
I20260812 06:19:14.088124 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.030s	user 0.007s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13644,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:14.088757 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:14.106069 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5230,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:14.106830 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:14.262135 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.155s	user 0.105s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":390,"lbm_read_time_us":8561,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24495,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:19:14.262804 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=11.118625
I20260812 06:19:14.300973 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.038s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12717750,"delete_count":0,"lbm_write_time_us":16237,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:14.301558 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:14.315313 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5131,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:14.315865 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:14.449460 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.133s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672283,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":9059,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27886,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:19:14.450300 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=10.126437
I20260812 06:19:14.495543 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.045s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15370,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.496075 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:14.507586 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4406,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.508462 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushMRSOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:14.538548 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushMRSOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1255,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1805,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:14.539390 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling LogGCOp(253c0dcb00e04eec895e8516aea99eea): free 108988752 bytes of WAL
I20260812 06:19:14.539700 29714 log_reader.cc:385] T 253c0dcb00e04eec895e8516aea99eea: removed 11 log segments from log reader
I20260812 06:19:14.539783 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000028 (ops 133-137)
I20260812 06:19:14.539842 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000029 (ops 138-142)
I20260812 06:19:14.539901 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000030 (ops 143-147)
I20260812 06:19:14.539945 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000031 (ops 148-152)
I20260812 06:19:14.539984 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000032 (ops 153-157)
I20260812 06:19:14.540023 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000033 (ops 158-162)
I20260812 06:19:14.540060 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000034 (ops 163-167)
I20260812 06:19:14.540110 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000035 (ops 168-172)
I20260812 06:19:14.540149 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000036 (ops 173-176)
I20260812 06:19:14.540210 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000037 (ops 177-181)
I20260812 06:19:14.540246 29714 log.cc:1079] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/253c0dcb00e04eec895e8516aea99eea/wal-000000038 (ops 182-186)
I20260812 06:19:14.565495 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: LogGCOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:14.566570 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=3.181125
I20260812 06:19:14.578913 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4307779,"delete_count":0,"lbm_write_time_us":4717,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:19:14.579401 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling UndoDeltaBlockGCOp(253c0dcb00e04eec895e8516aea99eea): 448 bytes on disk
I20260812 06:19:14.579833 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: UndoDeltaBlockGCOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:14.580345 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:14.592020 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.012s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3897533,"delete_count":0,"lbm_write_time_us":4233,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:14.592501 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:14.768388 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.176s	user 0.138s	sys 0.037s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877336,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1225,"lbm_read_time_us":12772,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35173,"lbm_writes_lt_1ms":643,"mutex_wait_us":309,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:19:14.769193 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=14.095187
I20260812 06:19:14.821491 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.052s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23598,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:14.822144 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea): perf score=2.188937
I20260812 06:19:14.834697 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: FlushDeltaMemStoresOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.835449 29786 maintenance_manager.cc:419] P 5a50fdce89cf4cefab54eb75abdef08d: Scheduling MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea): perf score=1.000000
I20260812 06:19:14.865305 29582 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.976s	user 1.779s	sys 0.201s
I20260812 06:19:14.920357 29582 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.054s	user 0.001s	sys 0.000s
I20260812 06:19:14.921074 29582 tablet_server.cc:179] TabletServer@127.28.227.129:0 shutting down...
I20260812 06:19:14.969877 29714 maintenance_manager.cc:643] P 5a50fdce89cf4cefab54eb75abdef08d: MajorDeltaCompactionOp(253c0dcb00e04eec895e8516aea99eea) complete. Timing: real 0.134s	user 0.100s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1127,"lbm_read_time_us":11124,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26962,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:19:14.970620 29582 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:14.971055 29582 tablet_replica.cc:333] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d: stopping tablet replica
I20260812 06:19:14.971314 29582 raft_consensus.cc:2243] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:14.971562 29582 raft_consensus.cc:2272] T 253c0dcb00e04eec895e8516aea99eea P 5a50fdce89cf4cefab54eb75abdef08d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:14.998337 29582 tablet_server.cc:196] TabletServer@127.28.227.129:0 shutdown complete.
I20260812 06:19:15.018217 29582 master.cc:562] Master@127.28.227.190:33991 shutting down...
I20260812 06:19:15.022488 29582 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:15.022727 29582 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:15.022835 29582 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2eb53e6ff21d4879b19f12f89806f154: stopping tablet replica
I20260812 06:19:15.035280 29582 master.cc:584] Master@127.28.227.190:33991 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5511 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:15.138682 29582 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.227.190:41705
I20260812 06:19:15.139197 29582 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:15.141716 29822 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:15.141750 29819 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:15.141736 29818 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:15.141919 29582 server_base.cc:1061] running on GCE node
I20260812 06:19:15.142146 29582 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:15.142212 29582 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:15.142237 29582 hybrid_clock.cc:648] HybridClock initialized: now 1786515555142237 us; error 0 us; skew 500 ppm
I20260812 06:19:15.143079 29582 webserver.cc:533] Webserver started at http://127.28.227.190:35683/ using document root <none> and password file <none>
I20260812 06:19:15.143258 29582 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:15.143327 29582 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:15.143435 29582 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:15.143858 29582 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/master-0-root/instance:
uuid: "6d3fc5c572f14a0597b8540e3e48f2ab"
format_stamp: "Formatted at 2026-08-12 06:19:15 on dist-test-slave-njxd"
I20260812 06:19:15.145444 29582 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:15.146517 29828 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:15.146826 29582 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:15.146919 29582 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/master-0-root
uuid: "6d3fc5c572f14a0597b8540e3e48f2ab"
format_stamp: "Formatted at 2026-08-12 06:19:15 on dist-test-slave-njxd"
I20260812 06:19:15.147009 29582 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:15.161183 29582 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:15.161748 29582 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:15.165769 29582 rpc_server.cc:307] RPC server started. Bound to: 127.28.227.190:41705
I20260812 06:19:15.167335 29888 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.227.190:41705 every 8 connection(s)
I20260812 06:19:15.167610 29889 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:15.172952 29889 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab: Bootstrap starting.
I20260812 06:19:15.173883 29889 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:15.174970 29889 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab: No bootstrap required, opened a new log
I20260812 06:19:15.175374 29889 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d3fc5c572f14a0597b8540e3e48f2ab" member_type: VOTER }
I20260812 06:19:15.175482 29889 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:15.175546 29889 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6d3fc5c572f14a0597b8540e3e48f2ab, State: Initialized, Role: FOLLOWER
I20260812 06:19:15.175763 29889 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [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: "6d3fc5c572f14a0597b8540e3e48f2ab" member_type: VOTER }
I20260812 06:19:15.175873 29889 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:15.175920 29889 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:15.175976 29889 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:15.176664 29889 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d3fc5c572f14a0597b8540e3e48f2ab" member_type: VOTER }
I20260812 06:19:15.176811 29889 leader_election.cc:304] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [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: 6d3fc5c572f14a0597b8540e3e48f2ab; no voters: 
I20260812 06:19:15.177029 29889 leader_election.cc:290] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:15.177158 29894 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:15.177397 29894 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 1 LEADER]: Becoming Leader. State: Replica: 6d3fc5c572f14a0597b8540e3e48f2ab, State: Running, Role: LEADER
I20260812 06:19:15.177506 29889 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:15.177620 29894 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [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: "6d3fc5c572f14a0597b8540e3e48f2ab" member_type: VOTER }
I20260812 06:19:15.178108 29895 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6d3fc5c572f14a0597b8540e3e48f2ab" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d3fc5c572f14a0597b8540e3e48f2ab" member_type: VOTER } }
I20260812 06:19:15.178143 29896 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6d3fc5c572f14a0597b8540e3e48f2ab. Latest consensus state: current_term: 1 leader_uuid: "6d3fc5c572f14a0597b8540e3e48f2ab" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d3fc5c572f14a0597b8540e3e48f2ab" member_type: VOTER } }
I20260812 06:19:15.178207 29895 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:15.178231 29896 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:15.178455 29900 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:15.179419 29900 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:15.179620 29582 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:15.181252 29900 catalog_manager.cc:1383] Generated new cluster ID: f83dc0def1ad41fbabd1551194248ac9
I20260812 06:19:15.181313 29900 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:15.192013 29900 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:15.192646 29900 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:15.205745 29900 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab: Generated new TSK 0
I20260812 06:19:15.206005 29900 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:15.212198 29582 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:15.214404 29916 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:15.214458 29582 server_base.cc:1061] running on GCE node
W20260812 06:19:15.214424 29915 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:15.214681 29918 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:15.214960 29582 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:15.215031 29582 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:15.215065 29582 hybrid_clock.cc:648] HybridClock initialized: now 1786515555215064 us; error 0 us; skew 500 ppm
I20260812 06:19:15.215926 29582 webserver.cc:533] Webserver started at http://127.28.227.129:45981/ using document root <none> and password file <none>
I20260812 06:19:15.216092 29582 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:15.216138 29582 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:15.216193 29582 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:15.216593 29582 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/instance:
uuid: "f652e96939e24100bc21314fdb0e2e1c"
format_stamp: "Formatted at 2026-08-12 06:19:15 on dist-test-slave-njxd"
I20260812 06:19:15.218192 29582 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:15.219060 29923 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:15.219290 29582 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:15.219354 29582 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root
uuid: "f652e96939e24100bc21314fdb0e2e1c"
format_stamp: "Formatted at 2026-08-12 06:19:15 on dist-test-slave-njxd"
I20260812 06:19:15.219466 29582 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:15.229677 29582 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:15.230115 29582 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:15.230443 29582 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:15.230929 29582 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:15.230991 29582 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:15.231056 29582 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:15.231117 29582 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:15.235692 29582 rpc_server.cc:307] RPC server started. Bound to: 127.28.227.129:39583
I20260812 06:19:15.238312 29995 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.227.129:39583 every 8 connection(s)
I20260812 06:19:15.243250 29996 heartbeater.cc:344] Connected to a master server at 127.28.227.190:41705
I20260812 06:19:15.243404 29996 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:15.243660 29996 heartbeater.cc:507] Master 127.28.227.190:41705 requested a full tablet report, sending...
I20260812 06:19:15.244395 29847 ts_manager.cc:194] Registered new tserver with Master: f652e96939e24100bc21314fdb0e2e1c (127.28.227.129:39583)
I20260812 06:19:15.244505 29582 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007855621s
I20260812 06:19:15.245185 29847 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39032
I20260812 06:19:15.252614 29847 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39040:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:15.261817 29954 tablet_service.cc:1511] Processing CreateTablet for tablet ee9c327be7804186834b7adb7a072f13 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d8ab6ba9d73e42be959e974009f22288]), partition=
I20260812 06:19:15.262135 29954 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ee9c327be7804186834b7adb7a072f13. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:15.264103 30009 tablet_bootstrap.cc:492] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Bootstrap starting.
I20260812 06:19:15.265012 30009 tablet_bootstrap.cc:654] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:15.266193 30009 tablet_bootstrap.cc:492] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: No bootstrap required, opened a new log
I20260812 06:19:15.266322 30009 ts_tablet_manager.cc:1403] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:15.266752 30009 raft_consensus.cc:359] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f652e96939e24100bc21314fdb0e2e1c" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 39583 } }
I20260812 06:19:15.266872 30009 raft_consensus.cc:385] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:15.266927 30009 raft_consensus.cc:740] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f652e96939e24100bc21314fdb0e2e1c, State: Initialized, Role: FOLLOWER
I20260812 06:19:15.267112 30009 consensus_queue.cc:260] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [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: "f652e96939e24100bc21314fdb0e2e1c" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 39583 } }
I20260812 06:19:15.267203 30009 raft_consensus.cc:399] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:15.267228 30009 raft_consensus.cc:493] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:15.267318 30009 raft_consensus.cc:3060] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:15.268128 30009 raft_consensus.cc:515] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f652e96939e24100bc21314fdb0e2e1c" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 39583 } }
I20260812 06:19:15.268303 30009 leader_election.cc:304] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [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: f652e96939e24100bc21314fdb0e2e1c; no voters: 
I20260812 06:19:15.268527 30009 leader_election.cc:290] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:15.268668 30011 raft_consensus.cc:2804] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:15.268918 30009 ts_tablet_manager.cc:1434] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:15.268927 30011 raft_consensus.cc:697] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 1 LEADER]: Becoming Leader. State: Replica: f652e96939e24100bc21314fdb0e2e1c, State: Running, Role: LEADER
I20260812 06:19:15.268937 29996 heartbeater.cc:499] Master 127.28.227.190:41705 was elected leader, sending a full tablet report...
I20260812 06:19:15.269172 30011 consensus_queue.cc:237] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [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: "f652e96939e24100bc21314fdb0e2e1c" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 39583 } }
I20260812 06:19:15.270658 29847 catalog_manager.cc:5719] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c reported cstate change: term changed from 0 to 1, leader changed from <none> to f652e96939e24100bc21314fdb0e2e1c (127.28.227.129). New cstate: current_term: 1 leader_uuid: "f652e96939e24100bc21314fdb0e2e1c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f652e96939e24100bc21314fdb0e2e1c" member_type: VOTER last_known_addr { host: "127.28.227.129" port: 39583 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:15.331409 29582 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.014s	sys 0.008s
I20260812 06:19:15.488899 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushMRSOp(ee9c327be7804186834b7adb7a072f13): perf score=19.054940
I20260812 06:19:15.646420 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushMRSOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.157s	user 0.116s	sys 0.040s Metrics: {"bytes_written":12717727,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1041,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39771,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":73088,"update_count":1550}
I20260812 06:19:15.647413 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling LogGCOp(ee9c327be7804186834b7adb7a072f13): free 20743880 bytes of WAL
I20260812 06:19:15.647670 29929 log_reader.cc:385] T ee9c327be7804186834b7adb7a072f13: removed 2 log segments from log reader
I20260812 06:19:15.647727 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000001 (ops 1-6)
I20260812 06:19:15.647768 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000002 (ops 7-11)
I20260812 06:19:15.652905 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: LogGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:15.653264 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling UndoDeltaBlockGCOp(ee9c327be7804186834b7adb7a072f13): 16411395 bytes on disk
I20260812 06:19:15.653723 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: UndoDeltaBlockGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:19:15.654134 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:15.680436 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.680869 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:15.691109 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3678,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:15.691607 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:15.876014 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.184s	user 0.125s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774790,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":611,"lbm_read_time_us":13573,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30753,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":339,"threads_started":5,"update_count":2500}
I20260812 06:19:15.876673 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:15.926192 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.049s	user 0.043s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21547,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.926740 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:15.937337 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3941,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.938144 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:16.110654 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.172s	user 0.132s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":257,"lbm_read_time_us":12551,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28217,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2500}
I20260812 06:19:16.111366 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:16.157075 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.157636 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:16.322894 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.165s	user 0.105s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":866,"lbm_read_time_us":11496,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27306,"lbm_writes_lt_1ms":443,"mutex_wait_us":490,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2000}
I20260812 06:19:16.323660 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=11.118625
I20260812 06:19:16.357537 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.034s	user 0.011s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14786,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:16.358074 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:16.382261 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5326,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.382737 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:16.393275 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.393782 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:16.593092 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.199s	user 0.110s	sys 0.079s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":397,"lbm_read_time_us":11558,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30936,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:16.593842 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:16.642344 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.048s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19740,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.642912 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:16.655010 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.655630 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:16.823067 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.167s	user 0.117s	sys 0.044s 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":1102,"lbm_read_time_us":11917,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31404,"lbm_writes_lt_1ms":543,"mutex_wait_us":339,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:19:16.823748 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=11.118625
I20260812 06:19:16.854722 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13393,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:16.855300 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:16.871618 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5645,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.872215 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushMRSOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:16.927942 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushMRSOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.056s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1442,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1715,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:16.928601 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling LogGCOp(ee9c327be7804186834b7adb7a072f13): free 112692379 bytes of WAL
I20260812 06:19:16.928839 29929 log_reader.cc:385] T ee9c327be7804186834b7adb7a072f13: removed 11 log segments from log reader
I20260812 06:19:16.928884 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000003 (ops 12-16)
I20260812 06:19:16.928916 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000004 (ops 17-21)
I20260812 06:19:16.928982 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000005 (ops 22-26)
I20260812 06:19:16.929028 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000006 (ops 27-31)
I20260812 06:19:16.929067 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000007 (ops 32-36)
I20260812 06:19:16.929108 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000008 (ops 37-41)
I20260812 06:19:16.929147 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000009 (ops 42-46)
I20260812 06:19:16.929184 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000010 (ops 47-51)
I20260812 06:19:16.929224 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000011 (ops 52-56)
I20260812 06:19:16.929270 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000012 (ops 57-61)
I20260812 06:19:16.929308 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000013 (ops 62-66)
I20260812 06:19:16.953270 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: LogGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:16.953812 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling UndoDeltaBlockGCOp(ee9c327be7804186834b7adb7a072f13): 462 bytes on disk
I20260812 06:19:16.954246 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: UndoDeltaBlockGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:16.954836 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=6.157687
I20260812 06:19:16.986655 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.032s	user 0.015s	sys 0.015s Metrics: {"bytes_written":8287127,"delete_count":0,"lbm_write_time_us":8914,"lbm_writes_lt_1ms":205,"reinsert_count":0,"update_count":1010}
I20260812 06:19:16.987358 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling LogGCOp(ee9c327be7804186834b7adb7a072f13): free 11564875 bytes of WAL
I20260812 06:19:16.987632 29929 log_reader.cc:385] T ee9c327be7804186834b7adb7a072f13: removed 1 log segments from log reader
I20260812 06:19:16.987708 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000014 (ops 67-70)
I20260812 06:19:16.990214 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: LogGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:16.990579 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:17.001281 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4020608,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:19:17.001772 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:17.266428 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.264s	user 0.149s	sys 0.105s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2183,"lbm_read_time_us":16993,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40264,"lbm_writes_lt_1ms":743,"mutex_wait_us":1458,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:19:17.267112 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=18.063937
I20260812 06:19:17.320447 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.053s	user 0.019s	sys 0.032s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":23499,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:17.320943 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:17.501345 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.180s	user 0.128s	sys 0.052s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774571,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":270,"lbm_read_time_us":11435,"lbm_reads_lt_1ms":563,"lbm_write_time_us":32909,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2500}
I20260812 06:19:17.502094 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:17.559343 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.057s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20682,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.559958 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:17.571365 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.011s	user 0.005s	sys 0.004s 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:19:17.571900 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:17.767131 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.195s	user 0.131s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":13452,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30301,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22400,"update_count":2500}
I20260812 06:19:17.767850 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:17.818517 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.050s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21202,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.819166 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:17.845323 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.026s	user 0.007s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.845932 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:18.035404 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.189s	user 0.112s	sys 0.077s 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":371,"lbm_read_time_us":14180,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29094,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:19:18.036000 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:18.085866 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.050s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22022,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.086508 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:18.102857 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.103840 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:18.293655 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.190s	user 0.111s	sys 0.064s 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":350,"lbm_read_time_us":9747,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29170,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:18.294329 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:18.349013 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.054s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22603,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.349561 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:18.361990 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4143,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.362638 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:18.527911 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.165s	user 0.116s	sys 0.045s 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":293,"lbm_read_time_us":11705,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34287,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":2500}
I20260812 06:19:18.528601 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=11.118625
I20260812 06:19:18.565191 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.036s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12717739,"delete_count":0,"lbm_write_time_us":15530,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:18.565953 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:18.582209 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5698,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.582720 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushMRSOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:18.635283 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushMRSOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.052s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1210,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2464,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:18.636009 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling LogGCOp(ee9c327be7804186834b7adb7a072f13): free 121459504 bytes of WAL
I20260812 06:19:18.636256 29929 log_reader.cc:385] T ee9c327be7804186834b7adb7a072f13: removed 12 log segments from log reader
I20260812 06:19:18.636304 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000015 (ops 71-75)
I20260812 06:19:18.636335 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000016 (ops 76-80)
I20260812 06:19:18.636401 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000017 (ops 81-85)
I20260812 06:19:18.636463 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000018 (ops 86-90)
I20260812 06:19:18.636508 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000019 (ops 91-95)
I20260812 06:19:18.636567 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000020 (ops 96-100)
I20260812 06:19:18.636595 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000021 (ops 101-105)
I20260812 06:19:18.636633 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000022 (ops 106-110)
I20260812 06:19:18.636672 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000023 (ops 111-115)
I20260812 06:19:18.636709 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000024 (ops 116-120)
I20260812 06:19:18.636749 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000025 (ops 121-125)
I20260812 06:19:18.636787 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000026 (ops 126-130)
I20260812 06:19:18.662724 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: LogGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:18.663249 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=7.149875
I20260812 06:19:18.701884 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.038s	user 0.007s	sys 0.030s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12228,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:18.702525 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling LogGCOp(ee9c327be7804186834b7adb7a072f13): free 11564893 bytes of WAL
I20260812 06:19:18.702768 29929 log_reader.cc:385] T ee9c327be7804186834b7adb7a072f13: removed 1 log segments from log reader
I20260812 06:19:18.702813 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000027 (ops 131-134)
I20260812 06:19:18.705030 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: LogGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:18.705374 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling UndoDeltaBlockGCOp(ee9c327be7804186834b7adb7a072f13): 493 bytes on disk
I20260812 06:19:18.705866 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: UndoDeltaBlockGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:18.706357 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:18.716881 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3738,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.717636 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:18.973760 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.256s	user 0.122s	sys 0.121s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":461,"lbm_read_time_us":17615,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38239,"lbm_writes_lt_1ms":743,"mutex_wait_us":54,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":89088,"thread_start_us":118,"threads_started":1,"update_count":3500}
I20260812 06:19:18.974534 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=18.063937
I20260812 06:19:19.041734 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.067s	user 0.041s	sys 0.019s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27887,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:19.042264 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:19.055135 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.055729 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:19.269613 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.214s	user 0.124s	sys 0.089s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1822,"lbm_read_time_us":16318,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35852,"lbm_writes_lt_1ms":643,"mutex_wait_us":307,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":3000}
I20260812 06:19:19.270413 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:19.324244 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.054s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24203,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.324801 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:19.335687 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.336369 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:19.521154 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.185s	user 0.107s	sys 0.075s 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":216,"lbm_read_time_us":12178,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35289,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":79,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:19:19.521870 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:19.579797 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.058s	user 0.027s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20840,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.580353 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:19.591434 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.591982 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:19.779944 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.188s	user 0.128s	sys 0.056s 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":135,"lbm_read_time_us":12450,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32537,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:19.780687 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=11.118625
I20260812 06:19:19.818826 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.038s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15579,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:19.819558 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:19.841398 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.022s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6695,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:19.841952 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:19.997764 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.156s	user 0.116s	sys 0.033s 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":182,"lbm_read_time_us":9116,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24064,"lbm_writes_lt_1ms":443,"mutex_wait_us":100,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.998559 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=14.095187
I20260812 06:19:20.049765 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.051s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20248,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.050369 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:20.062213 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4106,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.062700 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:20.215381 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.152s	user 0.116s	sys 0.036s 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":334,"lbm_read_time_us":11066,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31544,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:19:20.216229 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=10.126437
I20260812 06:19:20.251575 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.035s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15522,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:20.252166 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=2.188937
I20260812 06:19:20.269526 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.270367 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushMRSOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:20.299683 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushMRSOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":287,"dirs.run_wall_time_us":1374,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1736,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:20.300531 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling LogGCOp(ee9c327be7804186834b7adb7a072f13): free 121006692 bytes of WAL
I20260812 06:19:20.301023 29929 log_reader.cc:385] T ee9c327be7804186834b7adb7a072f13: removed 12 log segments from log reader
I20260812 06:19:20.301175 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000028 (ops 135-139)
I20260812 06:19:20.301323 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000029 (ops 140-144)
I20260812 06:19:20.301455 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000030 (ops 145-149)
I20260812 06:19:20.301548 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000031 (ops 150-154)
I20260812 06:19:20.301659 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000032 (ops 155-159)
I20260812 06:19:20.301720 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000033 (ops 160-164)
I20260812 06:19:20.301833 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000034 (ops 165-168)
I20260812 06:19:20.301921 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000035 (ops 169-173)
I20260812 06:19:20.301996 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000036 (ops 174-178)
I20260812 06:19:20.302065 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000037 (ops 179-183)
I20260812 06:19:20.302151 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000038 (ops 184-188)
I20260812 06:19:20.302232 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000039 (ops 189-193)
I20260812 06:19:20.329383 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: LogGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {"spinlock_wait_cycles":2304}
I20260812 06:19:20.329901 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling UndoDeltaBlockGCOp(ee9c327be7804186834b7adb7a072f13): 492 bytes on disk
I20260812 06:19:20.330333 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: UndoDeltaBlockGCOp(ee9c327be7804186834b7adb7a072f13) 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:19:20.330868 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13): perf score=6.157687
I20260812 06:19:20.358603 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: FlushDeltaMemStoresOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.028s	user 0.014s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9948,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:20.359117 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling LogGCOp(ee9c327be7804186834b7adb7a072f13): free 12017954 bytes of WAL
I20260812 06:19:20.359342 29929 log_reader.cc:385] T ee9c327be7804186834b7adb7a072f13: removed 1 log segments from log reader
I20260812 06:19:20.359386 29929 log.cc:1079] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: Deleting log segment in path: /tmp/dist-test-taskHs6Wh9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515549616638-29582-0/minicluster-data/ts-0-root/wals/ee9c327be7804186834b7adb7a072f13/wal-000000040 (ops 194-198)
I20260812 06:19:20.361816 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: LogGCOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:20.362154 29997 maintenance_manager.cc:419] P f652e96939e24100bc21314fdb0e2e1c: Scheduling MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13): perf score=1.000000
I20260812 06:19:20.419204 29582 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.088s	user 1.867s	sys 0.159s
I20260812 06:19:20.508647 29582 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.089s	user 0.002s	sys 0.000s
I20260812 06:19:20.509331 29582 tablet_server.cc:179] TabletServer@127.28.227.129:0 shutting down...
I20260812 06:19:20.524891 29929 maintenance_manager.cc:643] P f652e96939e24100bc21314fdb0e2e1c: MajorDeltaCompactionOp(ee9c327be7804186834b7adb7a072f13) complete. Timing: real 0.163s	user 0.121s	sys 0.041s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":675,"lbm_read_time_us":11805,"lbm_reads_lt_1ms":661,"lbm_write_time_us":30705,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24448,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:19:20.527307 29582 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:20.527637 29582 tablet_replica.cc:333] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c: stopping tablet replica
I20260812 06:19:20.527799 29582 raft_consensus.cc:2243] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:20.528000 29582 raft_consensus.cc:2272] T ee9c327be7804186834b7adb7a072f13 P f652e96939e24100bc21314fdb0e2e1c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:20.543460 29582 tablet_server.cc:196] TabletServer@127.28.227.129:0 shutdown complete.
I20260812 06:19:20.576000 29582 master.cc:562] Master@127.28.227.190:41705 shutting down...
I20260812 06:19:20.579715 29582 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:20.579986 29582 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:20.580077 29582 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6d3fc5c572f14a0597b8540e3e48f2ab: stopping tablet replica
I20260812 06:19:20.592970 29582 master.cc:584] Master@127.28.227.190:41705 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5539 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11052 ms total)

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