[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:37.262710 28651 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.250.254:41979
I20260812 06:18:37.263844 28651 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:37.264487 28651 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:37.271363 28669 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:37.271417 28651 server_base.cc:1061] running on GCE node
W20260812 06:18:37.271337 28665 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:37.271628 28666 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:37.272126 28651 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:37.272228 28651 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:37.272259 28651 hybrid_clock.cc:648] HybridClock initialized: now 1786515517272257 us; error 0 us; skew 500 ppm
I20260812 06:18:37.274055 28651 webserver.cc:533] Webserver started at http://127.27.250.254:40433/ using document root <none> and password file <none>
I20260812 06:18:37.274603 28651 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:37.274659 28651 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:37.274869 28651 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:37.276588 28651 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/master-0-root/instance:
uuid: "69362ca214304adb863f623b7fdb9898"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-jpj1"
I20260812 06:18:37.280129 28651 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:18:37.282279 28678 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:37.283565 28651 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:18:37.283682 28651 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/master-0-root
uuid: "69362ca214304adb863f623b7fdb9898"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-jpj1"
I20260812 06:18:37.283773 28651 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:37.301821 28651 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:37.302516 28651 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:37.302661 28651 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:37.310315 28782 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.250.254:41979 every 8 connection(s)
I20260812 06:18:37.310339 28651 rpc_server.cc:307] RPC server started. Bound to: 127.27.250.254:41979
I20260812 06:18:37.312740 28784 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:37.318356 28784 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898: Bootstrap starting.
I20260812 06:18:37.320761 28784 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:37.321673 28784 log.cc:826] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:37.323315 28784 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898: No bootstrap required, opened a new log
I20260812 06:18:37.326164 28784 raft_consensus.cc:359] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "69362ca214304adb863f623b7fdb9898" member_type: VOTER }
I20260812 06:18:37.326360 28784 raft_consensus.cc:385] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:37.326450 28784 raft_consensus.cc:740] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 69362ca214304adb863f623b7fdb9898, State: Initialized, Role: FOLLOWER
I20260812 06:18:37.327067 28784 consensus_queue.cc:260] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [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: "69362ca214304adb863f623b7fdb9898" member_type: VOTER }
I20260812 06:18:37.327215 28784 raft_consensus.cc:399] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:37.327289 28784 raft_consensus.cc:493] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:37.327415 28784 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:37.328233 28784 raft_consensus.cc:515] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "69362ca214304adb863f623b7fdb9898" member_type: VOTER }
I20260812 06:18:37.328678 28784 leader_election.cc:304] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [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: 69362ca214304adb863f623b7fdb9898; no voters: 
I20260812 06:18:37.328989 28784 leader_election.cc:290] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:37.329141 28790 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:37.329361 28790 raft_consensus.cc:697] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 1 LEADER]: Becoming Leader. State: Replica: 69362ca214304adb863f623b7fdb9898, State: Running, Role: LEADER
I20260812 06:18:37.329810 28790 consensus_queue.cc:237] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [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: "69362ca214304adb863f623b7fdb9898" member_type: VOTER }
I20260812 06:18:37.330034 28784 sys_catalog.cc:565] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:37.331818 28792 sys_catalog.cc:455] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 69362ca214304adb863f623b7fdb9898. Latest consensus state: current_term: 1 leader_uuid: "69362ca214304adb863f623b7fdb9898" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "69362ca214304adb863f623b7fdb9898" member_type: VOTER } }
I20260812 06:18:37.331957 28792 sys_catalog.cc:458] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:37.332199 28791 sys_catalog.cc:455] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "69362ca214304adb863f623b7fdb9898" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "69362ca214304adb863f623b7fdb9898" member_type: VOTER } }
I20260812 06:18:37.332261 28651 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:37.332280 28791 sys_catalog.cc:458] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:37.332273 28817 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:37.334602 28817 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:37.339370 28817 catalog_manager.cc:1383] Generated new cluster ID: 02f42910af5145f0910e09054a8f8374
I20260812 06:18:37.339454 28817 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:37.352497 28817 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:37.353361 28817 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:37.368913 28817 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898: Generated new TSK 0
I20260812 06:18:37.369593 28817 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:37.397159 28651 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:37.399935 28827 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:37.399935 28826 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:37.400068 28651 server_base.cc:1061] running on GCE node
W20260812 06:18:37.399926 28829 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:37.400444 28651 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:37.400496 28651 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:37.400517 28651 hybrid_clock.cc:648] HybridClock initialized: now 1786515517400517 us; error 0 us; skew 500 ppm
I20260812 06:18:37.401517 28651 webserver.cc:533] Webserver started at http://127.27.250.193:39597/ using document root <none> and password file <none>
I20260812 06:18:37.401703 28651 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:37.401764 28651 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:37.401849 28651 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:37.402303 28651 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/instance:
uuid: "bcefdb6a0f4e40ffb735928ccd3b0278"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-jpj1"
I20260812 06:18:37.404261 28651 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:37.406397 28839 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:37.407075 28651 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:18:37.407166 28651 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root
uuid: "bcefdb6a0f4e40ffb735928ccd3b0278"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-jpj1"
I20260812 06:18:37.407270 28651 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:37.418524 28651 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:37.419003 28651 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:37.419610 28651 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:37.420814 28651 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:37.420874 28651 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:37.420938 28651 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:37.420962 28651 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:37.427587 28651 rpc_server.cc:307] RPC server started. Bound to: 127.27.250.193:39015
I20260812 06:18:37.427649 28944 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.250.193:39015 every 8 connection(s)
I20260812 06:18:37.439318 28947 heartbeater.cc:344] Connected to a master server at 127.27.250.254:41979
I20260812 06:18:37.439663 28947 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:37.440254 28947 heartbeater.cc:507] Master 127.27.250.254:41979 requested a full tablet report, sending...
I20260812 06:18:37.442162 28706 ts_manager.cc:194] Registered new tserver with Master: bcefdb6a0f4e40ffb735928ccd3b0278 (127.27.250.193:39015)
I20260812 06:18:37.442327 28651 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0140146s
I20260812 06:18:37.443835 28706 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36248
I20260812 06:18:37.456382 28706 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36252:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:37.472911 28888 tablet_service.cc:1511] Processing CreateTablet for tablet 303b676cf2a2449e8bde75c94bc6897a (DEFAULT_TABLE table=heavy-update-compaction-test [id=ea14dcf03ea946a3a0e3e68bd37f7838]), partition=
I20260812 06:18:37.473388 28888 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 303b676cf2a2449e8bde75c94bc6897a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:37.475993 28973 tablet_bootstrap.cc:492] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Bootstrap starting.
I20260812 06:18:37.477218 28973 tablet_bootstrap.cc:654] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:37.479080 28973 tablet_bootstrap.cc:492] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: No bootstrap required, opened a new log
I20260812 06:18:37.479264 28973 ts_tablet_manager.cc:1403] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:37.479916 28973 raft_consensus.cc:359] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcefdb6a0f4e40ffb735928ccd3b0278" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 39015 } }
I20260812 06:18:37.480053 28973 raft_consensus.cc:385] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:37.480093 28973 raft_consensus.cc:740] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bcefdb6a0f4e40ffb735928ccd3b0278, State: Initialized, Role: FOLLOWER
I20260812 06:18:37.480239 28973 consensus_queue.cc:260] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [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: "bcefdb6a0f4e40ffb735928ccd3b0278" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 39015 } }
I20260812 06:18:37.480346 28973 raft_consensus.cc:399] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:37.480394 28973 raft_consensus.cc:493] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:37.480448 28973 raft_consensus.cc:3060] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:37.481514 28973 raft_consensus.cc:515] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcefdb6a0f4e40ffb735928ccd3b0278" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 39015 } }
I20260812 06:18:37.481665 28973 leader_election.cc:304] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [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: bcefdb6a0f4e40ffb735928ccd3b0278; no voters: 
I20260812 06:18:37.481920 28973 leader_election.cc:290] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:37.482053 28977 raft_consensus.cc:2804] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:37.482257 28973 ts_tablet_manager.cc:1434] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:37.482331 28977 raft_consensus.cc:697] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 1 LEADER]: Becoming Leader. State: Replica: bcefdb6a0f4e40ffb735928ccd3b0278, State: Running, Role: LEADER
I20260812 06:18:37.482560 28947 heartbeater.cc:499] Master 127.27.250.254:41979 was elected leader, sending a full tablet report...
I20260812 06:18:37.482532 28977 consensus_queue.cc:237] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [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: "bcefdb6a0f4e40ffb735928ccd3b0278" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 39015 } }
I20260812 06:18:37.485852 28706 catalog_manager.cc:5719] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 reported cstate change: term changed from 0 to 1, leader changed from <none> to bcefdb6a0f4e40ffb735928ccd3b0278 (127.27.250.193). New cstate: current_term: 1 leader_uuid: "bcefdb6a0f4e40ffb735928ccd3b0278" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcefdb6a0f4e40ffb735928ccd3b0278" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 39015 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:37.554814 28651 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.021s	sys 0.008s
I20260812 06:18:37.678907 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushMRSOp(303b676cf2a2449e8bde75c94bc6897a): perf score=15.086190
I20260812 06:18:37.809223 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushMRSOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.130s	user 0.088s	sys 0.040s Metrics: {"bytes_written":8779417,"cfile_init":1,"compiler_manager_pool.queue_time_us":213,"delete_count":0,"dirs.queue_time_us":111,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":979,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":30597,"lbm_writes_lt_1ms":581,"mutex_wait_us":193,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":291968,"thread_start_us":109,"threads_started":1,"update_count":1070}
I20260812 06:18:37.810312 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling LogGCOp(303b676cf2a2449e8bde75c94bc6897a): free 20743880 bytes of WAL
I20260812 06:18:37.810653 28849 log_reader.cc:385] T 303b676cf2a2449e8bde75c94bc6897a: removed 2 log segments from log reader
I20260812 06:18:37.810714 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000001 (ops 1-6)
I20260812 06:18:37.810990 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000002 (ops 7-11)
I20260812 06:18:37.816577 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: LogGCOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:37.817059 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling UndoDeltaBlockGCOp(303b676cf2a2449e8bde75c94bc6897a): 12719218 bytes on disk
I20260812 06:18:37.817871 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: UndoDeltaBlockGCOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.818390 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.196750
I20260812 06:18:37.829958 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":3828,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:18:37.830461 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:37.934870 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.104s	user 0.088s	sys 0.016s Metrics: {"cfile_cache_miss":322,"cfile_cache_miss_bytes":16159600,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":553,"lbm_read_time_us":6267,"lbm_reads_lt_1ms":350,"lbm_write_time_us":18648,"lbm_writes_lt_1ms":333,"mutex_wait_us":22,"peak_mem_usage":36812022,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":287,"threads_started":5,"update_count":1450}
I20260812 06:18:37.935379 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=7.149875
I20260812 06:18:37.960340 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.025s	user 0.014s	sys 0.010s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10881,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:37.961059 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:37.986056 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.025s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4889,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.986581 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:37.997219 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4052,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.997761 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:38.122265 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.124s	user 0.104s	sys 0.020s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672387,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":283,"lbm_read_time_us":8783,"lbm_reads_lt_1ms":473,"lbm_write_time_us":24524,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:18:38.122711 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:38.176180 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.053s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14950,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.176798 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:38.187371 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.187881 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:38.337594 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.150s	user 0.105s	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":348,"lbm_read_time_us":10482,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25532,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.338161 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:38.379231 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.041s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16423,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.379738 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:38.395473 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5714,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.396214 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:38.518493 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.122s	user 0.101s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":971,"lbm_read_time_us":8891,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24026,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:38.518988 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:38.554751 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.036s	user 0.010s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13823,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.555286 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:38.570374 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5558,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.570842 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:38.693341 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.122s	user 0.106s	sys 0.016s 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":218,"lbm_read_time_us":8438,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23176,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:38.693822 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:38.732501 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.039s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16063,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.733062 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:38.743487 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.744046 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:38.861440 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.117s	user 0.093s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":8493,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21071,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.862318 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:38.904331 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.042s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13821,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.904911 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:38.920542 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.921073 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:39.057668 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.136s	user 0.088s	sys 0.049s 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":164,"lbm_read_time_us":10750,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22068,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:39.058779 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:39.098209 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.039s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14509,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.098847 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:39.110441 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.110934 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushMRSOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:39.138890 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushMRSOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1186,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1571,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:39.139894 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling LogGCOp(303b676cf2a2449e8bde75c94bc6897a): free 124710299 bytes of WAL
I20260812 06:18:39.140133 28849 log_reader.cc:385] T 303b676cf2a2449e8bde75c94bc6897a: removed 12 log segments from log reader
I20260812 06:18:39.140184 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000003 (ops 12-16)
I20260812 06:18:39.140211 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000004 (ops 17-21)
I20260812 06:18:39.140228 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000005 (ops 22-26)
I20260812 06:18:39.140256 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000006 (ops 27-31)
I20260812 06:18:39.140297 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000007 (ops 32-36)
I20260812 06:18:39.140332 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000008 (ops 37-41)
I20260812 06:18:39.140354 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000009 (ops 42-46)
I20260812 06:18:39.140386 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000010 (ops 47-51)
I20260812 06:18:39.140419 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000011 (ops 52-56)
I20260812 06:18:39.140450 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000012 (ops 57-61)
I20260812 06:18:39.140481 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000013 (ops 62-66)
I20260812 06:18:39.140513 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000014 (ops 67-71)
I20260812 06:18:39.164877 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: LogGCOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:39.165407 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=3.181125
I20260812 06:18:39.185643 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.020s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:39.186215 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:39.200650 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5237,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.201237 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:39.396260 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.195s	user 0.145s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":143,"lbm_read_time_us":13593,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31343,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":25856,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:39.396785 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling UndoDeltaBlockGCOp(303b676cf2a2449e8bde75c94bc6897a): 472 bytes on disk
I20260812 06:18:39.397258 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: UndoDeltaBlockGCOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.397778 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=14.095187
I20260812 06:18:39.457445 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.060s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19989,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.458029 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:39.468693 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.469228 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:39.640869 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.171s	user 0.099s	sys 0.068s 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":5006,"lbm_read_time_us":12121,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28878,"lbm_writes_lt_1ms":543,"mutex_wait_us":2387,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:18:39.641507 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=11.118625
I20260812 06:18:39.678248 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.037s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15184,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:39.678882 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:39.699571 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.020s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4335,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:18:39.700047 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:39.721480 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.021s	user 0.012s	sys 0.007s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4924,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:39.722023 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:39.892592 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.170s	user 0.105s	sys 0.063s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2288,"lbm_read_time_us":13076,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27255,"lbm_writes_lt_1ms":543,"mutex_wait_us":582,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:39.893273 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=11.118625
I20260812 06:18:39.928653 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.035s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14645,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:39.929255 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:39.946875 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4901,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.947429 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:40.069190 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.122s	user 0.092s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":8871,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22390,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:40.071369 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:40.104075 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":12471588,"delete_count":0,"lbm_write_time_us":13961,"lbm_writes_lt_1ms":307,"mutex_wait_us":301,"reinsert_count":0,"update_count":1520}
I20260812 06:18:40.104588 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:40.114916 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":3541,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:40.115345 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:40.238647 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.123s	user 0.095s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":8454,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23418,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2000}
I20260812 06:18:40.239168 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:40.282593 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.043s	user 0.007s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14601,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.283121 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:40.293169 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.293820 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:40.414090 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.120s	user 0.091s	sys 0.027s 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":184,"lbm_read_time_us":8295,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22894,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:40.414667 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:40.459641 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.045s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14254,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.460207 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:40.470649 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.471104 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushMRSOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:40.513803 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushMRSOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.043s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1499,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1879,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:40.514595 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling LogGCOp(303b676cf2a2449e8bde75c94bc6897a): free 112692385 bytes of WAL
I20260812 06:18:40.514822 28849 log_reader.cc:385] T 303b676cf2a2449e8bde75c94bc6897a: removed 11 log segments from log reader
I20260812 06:18:40.514869 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000015 (ops 72-76)
I20260812 06:18:40.514899 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000016 (ops 77-81)
I20260812 06:18:40.514931 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000017 (ops 82-86)
I20260812 06:18:40.514966 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000018 (ops 87-91)
I20260812 06:18:40.514990 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000019 (ops 92-96)
I20260812 06:18:40.515021 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000020 (ops 97-101)
I20260812 06:18:40.515054 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000021 (ops 102-106)
I20260812 06:18:40.515086 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000022 (ops 107-111)
I20260812 06:18:40.515120 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000023 (ops 112-116)
I20260812 06:18:40.515151 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000024 (ops 117-121)
I20260812 06:18:40.515184 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000025 (ops 122-126)
I20260812 06:18:40.536223 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: LogGCOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.021s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:40.536644 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling UndoDeltaBlockGCOp(303b676cf2a2449e8bde75c94bc6897a): 446 bytes on disk
I20260812 06:18:40.537186 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: UndoDeltaBlockGCOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.537945 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:40.561406 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.023s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.561947 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:40.577062 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.015s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5642,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.577646 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:40.765138 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.187s	user 0.123s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":240,"lbm_read_time_us":13192,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32856,"lbm_writes_lt_1ms":643,"mutex_wait_us":64,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"thread_start_us":100,"threads_started":1,"update_count":3000}
I20260812 06:18:40.765703 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=14.095187
I20260812 06:18:40.812103 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18982,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.812562 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:40.953649 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.141s	user 0.103s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":198,"lbm_read_time_us":9419,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22392,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":2000}
I20260812 06:18:40.954176 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=14.095187
I20260812 06:18:41.001230 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.047s	user 0.017s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18912,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.001754 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:41.013243 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.013918 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:41.189190 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.175s	user 0.122s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":975,"lbm_read_time_us":10288,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28112,"lbm_writes_lt_1ms":543,"mutex_wait_us":300,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:41.189729 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=14.095187
I20260812 06:18:41.230247 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.040s	user 0.033s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17464,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.230827 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:41.242838 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.243618 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:41.400038 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.156s	user 0.105s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":5763,"lbm_read_time_us":11496,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28044,"lbm_writes_lt_1ms":543,"mutex_wait_us":2614,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:41.400794 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=11.118625
I20260812 06:18:41.438431 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.037s	user 0.029s	sys 0.004s Metrics: {"bytes_written":13251052,"delete_count":0,"lbm_write_time_us":15599,"lbm_writes_lt_1ms":326,"reinsert_count":0,"update_count":1615}
I20260812 06:18:41.439028 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:41.456625 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.017s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3569334,"delete_count":0,"lbm_write_time_us":3555,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:18:41.457199 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:41.467046 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3455,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.467768 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:41.612828 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.145s	user 0.103s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774791,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":628,"lbm_read_time_us":9083,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30894,"lbm_writes_lt_1ms":543,"mutex_wait_us":297,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:41.613384 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=11.118625
I20260812 06:18:41.646335 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.033s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13658,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:41.647153 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:41.660027 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4703,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.660502 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:41.780860 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.120s	user 0.096s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":680,"lbm_read_time_us":7128,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23106,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:41.781446 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=10.126437
I20260812 06:18:41.822934 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.041s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16025,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.823465 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:41.834259 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.834944 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushMRSOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:41.865257 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushMRSOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.030s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1444,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1382,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:41.865984 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling LogGCOp(303b676cf2a2449e8bde75c94bc6897a): free 120553636 bytes of WAL
I20260812 06:18:41.866214 28849 log_reader.cc:385] T 303b676cf2a2449e8bde75c94bc6897a: removed 12 log segments from log reader
I20260812 06:18:41.866272 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000026 (ops 127-130)
I20260812 06:18:41.866312 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000027 (ops 131-135)
I20260812 06:18:41.866343 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000028 (ops 136-140)
I20260812 06:18:41.866365 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000029 (ops 141-144)
I20260812 06:18:41.866393 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000030 (ops 145-149)
I20260812 06:18:41.866425 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000031 (ops 150-154)
I20260812 06:18:41.866456 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000032 (ops 155-159)
I20260812 06:18:41.866483 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000033 (ops 160-164)
I20260812 06:18:41.866510 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000034 (ops 165-169)
I20260812 06:18:41.866537 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000035 (ops 170-174)
I20260812 06:18:41.866569 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000036 (ops 175-179)
I20260812 06:18:41.866600 28849 log.cc:1079] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/303b676cf2a2449e8bde75c94bc6897a/wal-000000037 (ops 180-184)
I20260812 06:18:41.894604 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: LogGCOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:41.895032 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling UndoDeltaBlockGCOp(303b676cf2a2449e8bde75c94bc6897a): 462 bytes on disk
I20260812 06:18:41.895613 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: UndoDeltaBlockGCOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.896181 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=3.181125
I20260812 06:18:41.913653 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6779,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:41.914093 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:41.923709 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3547,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.924144 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:42.078482 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.154s	user 0.122s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":140,"lbm_read_time_us":11118,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32293,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:42.079028 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=14.095187
I20260812 06:18:42.133503 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.054s	user 0.021s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22507,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.134231 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a): perf score=2.188937
I20260812 06:18:42.150346 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: FlushDeltaMemStoresOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.150974 28948 maintenance_manager.cc:419] P bcefdb6a0f4e40ffb735928ccd3b0278: Scheduling MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a): perf score=1.000000
I20260812 06:18:42.204478 28651 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.650s	user 1.703s	sys 0.137s
I20260812 06:18:42.262816 28651 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.058s	user 0.001s	sys 0.000s
I20260812 06:18:42.263520 28651 tablet_server.cc:179] TabletServer@127.27.250.193:0 shutting down...
I20260812 06:18:42.282003 28849 maintenance_manager.cc:643] P bcefdb6a0f4e40ffb735928ccd3b0278: MajorDeltaCompactionOp(303b676cf2a2449e8bde75c94bc6897a) complete. Timing: real 0.131s	user 0.114s	sys 0.015s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":387,"lbm_read_time_us":9015,"lbm_reads_lt_1ms":560,"lbm_write_time_us":23389,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:18:42.283215 28651 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:42.283636 28651 tablet_replica.cc:333] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278: stopping tablet replica
I20260812 06:18:42.283915 28651 raft_consensus.cc:2243] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:42.284145 28651 raft_consensus.cc:2272] T 303b676cf2a2449e8bde75c94bc6897a P bcefdb6a0f4e40ffb735928ccd3b0278 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:42.300750 28651 tablet_server.cc:196] TabletServer@127.27.250.193:0 shutdown complete.
I20260812 06:18:42.327837 28651 master.cc:562] Master@127.27.250.254:41979 shutting down...
I20260812 06:18:42.331373 28651 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:42.331588 28651 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:42.331673 28651 tablet_replica.cc:333] T 00000000000000000000000000000000 P 69362ca214304adb863f623b7fdb9898: stopping tablet replica
I20260812 06:18:42.343931 28651 master.cc:584] Master@127.27.250.254:41979 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5161 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:42.424300 28651 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.250.254:35085
I20260812 06:18:42.424683 28651 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:42.426734 29011 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.426863 28651 server_base.cc:1061] running on GCE node
W20260812 06:18:42.426771 29013 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:42.426795 29010 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.427233 28651 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:42.427278 28651 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:42.427292 28651 hybrid_clock.cc:648] HybridClock initialized: now 1786515522427292 us; error 0 us; skew 500 ppm
I20260812 06:18:42.428093 28651 webserver.cc:533] Webserver started at http://127.27.250.254:33225/ using document root <none> and password file <none>
I20260812 06:18:42.428246 28651 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:42.428293 28651 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:42.428370 28651 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:42.428844 28651 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/master-0-root/instance:
uuid: "9ebf32b7f43f4973819f9bf57a6c10a7"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-jpj1"
I20260812 06:18:42.430387 28651 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:42.431299 29020 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.431521 28651 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:42.431610 28651 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/master-0-root
uuid: "9ebf32b7f43f4973819f9bf57a6c10a7"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-jpj1"
I20260812 06:18:42.431684 28651 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:42.439091 28651 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:42.439417 28651 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:42.443326 28651 rpc_server.cc:307] RPC server started. Bound to: 127.27.250.254:35085
I20260812 06:18:42.455822 29128 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.250.254:35085 every 8 connection(s)
I20260812 06:18:42.456401 29131 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:42.459110 29131 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7: Bootstrap starting.
I20260812 06:18:42.460263 29131 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:42.463449 29131 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7: No bootstrap required, opened a new log
I20260812 06:18:42.464048 29131 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ebf32b7f43f4973819f9bf57a6c10a7" member_type: VOTER }
I20260812 06:18:42.464162 29131 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:42.464195 29131 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9ebf32b7f43f4973819f9bf57a6c10a7, State: Initialized, Role: FOLLOWER
I20260812 06:18:42.464350 29131 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [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: "9ebf32b7f43f4973819f9bf57a6c10a7" member_type: VOTER }
I20260812 06:18:42.464439 29131 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:42.464480 29131 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:42.464529 29131 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:42.465337 29131 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ebf32b7f43f4973819f9bf57a6c10a7" member_type: VOTER }
I20260812 06:18:42.465462 29131 leader_election.cc:304] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [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: 9ebf32b7f43f4973819f9bf57a6c10a7; no voters: 
I20260812 06:18:42.465655 29131 leader_election.cc:290] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:42.465824 29135 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:42.466025 29135 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 1 LEADER]: Becoming Leader. State: Replica: 9ebf32b7f43f4973819f9bf57a6c10a7, State: Running, Role: LEADER
I20260812 06:18:42.466104 29131 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:42.466202 29135 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [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: "9ebf32b7f43f4973819f9bf57a6c10a7" member_type: VOTER }
I20260812 06:18:42.466660 29136 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9ebf32b7f43f4973819f9bf57a6c10a7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ebf32b7f43f4973819f9bf57a6c10a7" member_type: VOTER } }
I20260812 06:18:42.466802 29136 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:42.466681 29137 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9ebf32b7f43f4973819f9bf57a6c10a7. Latest consensus state: current_term: 1 leader_uuid: "9ebf32b7f43f4973819f9bf57a6c10a7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ebf32b7f43f4973819f9bf57a6c10a7" member_type: VOTER } }
I20260812 06:18:42.467089 29137 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:42.467473 29144 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:42.468170 29144 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:42.468364 28651 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:42.470013 29144 catalog_manager.cc:1383] Generated new cluster ID: 94a93ab9374d4e299fae317755ac9f84
I20260812 06:18:42.470072 29144 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:42.484480 29144 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:42.485047 29144 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:42.496357 29144 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7: Generated new TSK 0
I20260812 06:18:42.496546 29144 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:42.500736 28651 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:42.502599 29165 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.502696 28651 server_base.cc:1061] running on GCE node
W20260812 06:18:42.502832 29170 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:42.502786 29166 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.503087 28651 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:42.503135 28651 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:42.503157 28651 hybrid_clock.cc:648] HybridClock initialized: now 1786515522503156 us; error 0 us; skew 500 ppm
I20260812 06:18:42.504012 28651 webserver.cc:533] Webserver started at http://127.27.250.193:43427/ using document root <none> and password file <none>
I20260812 06:18:42.504172 28651 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:42.504249 28651 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:42.504333 28651 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:42.504724 28651 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/instance:
uuid: "af323282bcf74c9d841bce3844ffb86d"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-jpj1"
I20260812 06:18:42.506168 28651 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:42.507057 29179 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.507283 28651 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:42.507359 28651 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root
uuid: "af323282bcf74c9d841bce3844ffb86d"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-jpj1"
I20260812 06:18:42.507427 28651 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:42.518275 28651 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:42.518683 28651 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:42.518998 28651 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:42.519485 28651 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:42.519526 28651 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.519610 28651 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:42.519639 28651 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.523890 28651 rpc_server.cc:307] RPC server started. Bound to: 127.27.250.193:42189
I20260812 06:18:42.524260 29305 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.250.193:42189 every 8 connection(s)
I20260812 06:18:42.531643 29306 heartbeater.cc:344] Connected to a master server at 127.27.250.254:35085
I20260812 06:18:42.531790 29306 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:42.532027 29306 heartbeater.cc:507] Master 127.27.250.254:35085 requested a full tablet report, sending...
I20260812 06:18:42.532716 29053 ts_manager.cc:194] Registered new tserver with Master: af323282bcf74c9d841bce3844ffb86d (127.27.250.193:42189)
I20260812 06:18:42.533241 28651 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008835892s
I20260812 06:18:42.533591 29053 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59002
I20260812 06:18:42.539808 29053 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59018:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:42.548168 29239 tablet_service.cc:1511] Processing CreateTablet for tablet 8bb474e7d86e49f6a1bd88d4ea87f3b8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0cb5715f4e924a71a15bcb96ef9fb12a]), partition=
I20260812 06:18:42.548415 29239 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8bb474e7d86e49f6a1bd88d4ea87f3b8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:42.550395 29337 tablet_bootstrap.cc:492] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Bootstrap starting.
I20260812 06:18:42.551297 29337 tablet_bootstrap.cc:654] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:42.552340 29337 tablet_bootstrap.cc:492] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: No bootstrap required, opened a new log
I20260812 06:18:42.552415 29337 ts_tablet_manager.cc:1403] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:42.552800 29337 raft_consensus.cc:359] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af323282bcf74c9d841bce3844ffb86d" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 42189 } }
I20260812 06:18:42.552886 29337 raft_consensus.cc:385] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:42.552918 29337 raft_consensus.cc:740] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: af323282bcf74c9d841bce3844ffb86d, State: Initialized, Role: FOLLOWER
I20260812 06:18:42.553046 29337 consensus_queue.cc:260] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [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: "af323282bcf74c9d841bce3844ffb86d" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 42189 } }
I20260812 06:18:42.553115 29337 raft_consensus.cc:399] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:42.553156 29337 raft_consensus.cc:493] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:42.553205 29337 raft_consensus.cc:3060] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:42.553937 29337 raft_consensus.cc:515] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af323282bcf74c9d841bce3844ffb86d" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 42189 } }
I20260812 06:18:42.554068 29337 leader_election.cc:304] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [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: af323282bcf74c9d841bce3844ffb86d; no voters: 
I20260812 06:18:42.554220 29337 leader_election.cc:290] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:42.554322 29344 raft_consensus.cc:2804] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:42.554497 29337 ts_tablet_manager.cc:1434] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:42.554522 29306 heartbeater.cc:499] Master 127.27.250.254:35085 was elected leader, sending a full tablet report...
I20260812 06:18:42.554525 29344 raft_consensus.cc:697] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 1 LEADER]: Becoming Leader. State: Replica: af323282bcf74c9d841bce3844ffb86d, State: Running, Role: LEADER
I20260812 06:18:42.554735 29344 consensus_queue.cc:237] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [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: "af323282bcf74c9d841bce3844ffb86d" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 42189 } }
I20260812 06:18:42.556028 29053 catalog_manager.cc:5719] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d reported cstate change: term changed from 0 to 1, leader changed from <none> to af323282bcf74c9d841bce3844ffb86d (127.27.250.193). New cstate: current_term: 1 leader_uuid: "af323282bcf74c9d841bce3844ffb86d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af323282bcf74c9d841bce3844ffb86d" member_type: VOTER last_known_addr { host: "127.27.250.193" port: 42189 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:42.612231 28651 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.023s	sys 0.000s
I20260812 06:18:42.774888 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushMRSOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=23.023690
I20260812 06:18:42.927908 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushMRSOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.153s	user 0.110s	sys 0.040s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1064,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40351,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:42.928709 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling LogGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): free 20743880 bytes of WAL
I20260812 06:18:42.928969 29189 log_reader.cc:385] T 8bb474e7d86e49f6a1bd88d4ea87f3b8: removed 2 log segments from log reader
I20260812 06:18:42.929020 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000001 (ops 1-6)
I20260812 06:18:42.929061 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000002 (ops 7-11)
I20260812 06:18:42.932861 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: LogGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:42.933248 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:42.953724 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.020s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.954257 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:43.102795 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.148s	user 0.119s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":626,"lbm_read_time_us":10100,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23907,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":283,"threads_started":5,"update_count":2000}
I20260812 06:18:43.103505 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=14.095187
I20260812 06:18:43.155848 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.052s	user 0.033s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18773,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.156368 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling UndoDeltaBlockGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): 20513812 bytes on disk
I20260812 06:18:43.156795 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: UndoDeltaBlockGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.157223 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:43.168211 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.168970 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:43.354804 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.186s	user 0.130s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1028,"lbm_read_time_us":13685,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27961,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":45184,"update_count":2500}
I20260812 06:18:43.355407 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=14.095187
I20260812 06:18:43.399677 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.044s	user 0.020s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19725,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.400214 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:43.559851 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.159s	user 0.082s	sys 0.073s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713151,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2113,"lbm_read_time_us":11955,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25501,"lbm_writes_lt_1ms":443,"mutex_wait_us":1638,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:43.560472 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=11.118625
I20260812 06:18:43.597270 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15849,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.598047 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:43.612054 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.014s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4601,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.612589 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:43.743633 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.131s	user 0.091s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":425,"lbm_read_time_us":7927,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25118,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2000}
I20260812 06:18:43.744103 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=10.126437
I20260812 06:18:43.776516 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.032s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13852,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.777020 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:43.791757 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.792303 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:43.914623 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.122s	user 0.082s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":122,"lbm_read_time_us":7855,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25064,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:18:43.915721 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=10.126437
I20260812 06:18:43.959908 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.044s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18519,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.960505 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:43.971153 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.971827 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:44.092597 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.121s	user 0.082s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":562,"lbm_read_time_us":8733,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21481,"lbm_writes_lt_1ms":443,"mutex_wait_us":303,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:18:44.093220 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=10.126437
I20260812 06:18:44.145357 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.052s	user 0.028s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16264,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.146013 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:44.156535 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3942,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.157021 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushMRSOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:44.186339 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushMRSOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1275,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1467,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:44.187091 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling UndoDeltaBlockGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): 463 bytes on disk
I20260812 06:18:44.187664 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: UndoDeltaBlockGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"spinlock_wait_cycles":1280}
I20260812 06:18:44.188235 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:44.344636 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.156s	user 0.110s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1223,"lbm_read_time_us":10016,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24466,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:18:44.345256 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling LogGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): free 120553370 bytes of WAL
I20260812 06:18:44.345489 29189 log_reader.cc:385] T 8bb474e7d86e49f6a1bd88d4ea87f3b8: removed 12 log segments from log reader
I20260812 06:18:44.345535 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000003 (ops 12-16)
I20260812 06:18:44.345579 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000004 (ops 17-20)
I20260812 06:18:44.345614 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000005 (ops 21-25)
I20260812 06:18:44.345649 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000006 (ops 26-30)
I20260812 06:18:44.345711 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000007 (ops 31-35)
I20260812 06:18:44.345748 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000008 (ops 36-40)
I20260812 06:18:44.345884 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000009 (ops 41-45)
I20260812 06:18:44.345957 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000010 (ops 46-50)
I20260812 06:18:44.346022 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000011 (ops 51-54)
I20260812 06:18:44.346060 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000012 (ops 55-59)
I20260812 06:18:44.346114 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000013 (ops 60-64)
I20260812 06:18:44.346148 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000014 (ops 65-69)
I20260812 06:18:44.377790 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: LogGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.032s	user 0.003s	sys 0.027s Metrics: {}
I20260812 06:18:44.378353 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=15.087375
I20260812 06:18:44.437759 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.059s	user 0.032s	sys 0.015s Metrics: {"bytes_written":17558582,"delete_count":0,"lbm_write_time_us":21819,"lbm_writes_lt_1ms":431,"mutex_wait_us":70,"reinsert_count":0,"update_count":2140}
I20260812 06:18:44.438349 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=5.165500
I20260812 06:18:44.467370 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.029s	user 0.008s	sys 0.008s Metrics: {"bytes_written":7056408,"delete_count":0,"lbm_write_time_us":7257,"lbm_writes_lt_1ms":175,"reinsert_count":0,"update_count":860}
I20260812 06:18:44.467981 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:44.670264 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.202s	user 0.116s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918107,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":967,"lbm_read_time_us":15352,"lbm_reads_lt_1ms":664,"lbm_write_time_us":31896,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":3000}
I20260812 06:18:44.670759 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=18.063937
I20260812 06:18:44.744602 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.074s	user 0.053s	sys 0.018s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28289,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:44.745222 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:44.755971 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.756428 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:44.953557 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.197s	user 0.125s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":359,"lbm_read_time_us":13458,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32911,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":3000}
I20260812 06:18:44.954255 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=14.095187
I20260812 06:18:44.998246 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.044s	user 0.024s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19313,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.998714 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:45.011523 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4704,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.012282 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:45.189666 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.177s	user 0.103s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":632,"lbm_read_time_us":13478,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29187,"lbm_writes_lt_1ms":543,"mutex_wait_us":313,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:45.190253 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=14.095187
I20260812 06:18:45.249334 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.059s	user 0.039s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20095,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.249976 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:45.260625 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.261096 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:45.437747 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.176s	user 0.100s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":417,"lbm_read_time_us":13394,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28298,"lbm_writes_lt_1ms":543,"mutex_wait_us":203,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:45.438412 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=11.118625
I20260812 06:18:45.476006 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.037s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12717739,"delete_count":0,"lbm_write_time_us":17164,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.476591 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:45.506816 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.030s	user 0.009s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.507400 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:45.517504 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3577,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.518021 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:45.708318 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.190s	user 0.130s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":965,"lbm_read_time_us":13245,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28312,"lbm_writes_lt_1ms":543,"mutex_wait_us":354,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2500}
I20260812 06:18:45.708855 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=14.095187
I20260812 06:18:45.758149 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.049s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19114,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.758708 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:45.769667 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3885,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.770280 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushMRSOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:45.807868 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushMRSOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.037s	user 0.024s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":289,"dirs.run_wall_time_us":1458,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1637,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:45.808596 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling LogGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): free 133024342 bytes of WAL
I20260812 06:18:45.808844 29189 log_reader.cc:385] T 8bb474e7d86e49f6a1bd88d4ea87f3b8: removed 13 log segments from log reader
I20260812 06:18:45.808907 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000015 (ops 70-74)
I20260812 06:18:45.808948 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000016 (ops 75-78)
I20260812 06:18:45.808977 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000017 (ops 79-83)
I20260812 06:18:45.809010 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000018 (ops 84-88)
I20260812 06:18:45.809041 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000019 (ops 89-93)
I20260812 06:18:45.809068 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000020 (ops 94-98)
I20260812 06:18:45.809093 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000021 (ops 99-103)
I20260812 06:18:45.809119 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000022 (ops 104-108)
I20260812 06:18:45.809149 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000023 (ops 109-113)
I20260812 06:18:45.809180 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000024 (ops 114-118)
I20260812 06:18:45.809209 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000025 (ops 119-123)
I20260812 06:18:45.809235 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000026 (ops 124-128)
I20260812 06:18:45.809254 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000027 (ops 129-133)
I20260812 06:18:45.839664 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: LogGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.031s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:45.840070 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling UndoDeltaBlockGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): 491 bytes on disk
I20260812 06:18:45.840566 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: UndoDeltaBlockGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.841207 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=3.181125
I20260812 06:18:45.854998 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4095,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:45.855480 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:45.865028 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3415,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.865607 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:46.111352 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.246s	user 0.147s	sys 0.090s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":253,"lbm_read_time_us":16282,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36203,"lbm_writes_lt_1ms":743,"mutex_wait_us":26,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":31232,"thread_start_us":99,"threads_started":1,"update_count":3500}
I20260812 06:18:46.111989 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=18.063937
I20260812 06:18:46.181005 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.069s	user 0.033s	sys 0.019s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":24077,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:46.181545 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:46.193216 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.193867 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:46.383596 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.190s	user 0.130s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":13303,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31500,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":3000}
I20260812 06:18:46.384275 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=15.087375
I20260812 06:18:46.423045 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.039s	user 0.022s	sys 0.013s Metrics: {"bytes_written":16656046,"delete_count":0,"lbm_write_time_us":17016,"lbm_writes_lt_1ms":409,"reinsert_count":0,"update_count":2030}
I20260812 06:18:46.423727 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:46.441239 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.017s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":6613,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:46.441836 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:46.604773 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.163s	user 0.105s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815678,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":329,"lbm_read_time_us":12240,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26859,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:18:46.605337 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=14.095187
I20260812 06:18:46.661857 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.056s	user 0.043s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23481,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.662413 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:46.673139 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.673648 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:46.863668 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.188s	user 0.142s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1054,"lbm_read_time_us":12362,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29762,"lbm_writes_lt_1ms":543,"mutex_wait_us":357,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:46.864212 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=14.095187
I20260812 06:18:46.921458 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.057s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17645,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.922118 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:46.933154 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.933631 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:47.113940 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.180s	user 0.136s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":838,"lbm_read_time_us":13058,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28696,"lbm_writes_lt_1ms":543,"mutex_wait_us":309,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:18:47.114537 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=11.118625
I20260812 06:18:47.154688 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.040s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":14338,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:47.155172 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:47.177470 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.022s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.178169 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:47.192811 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5288,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.193465 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushMRSOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:47.236734 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushMRSOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.043s	user 0.027s	sys 0.002s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1413,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1526,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:47.237603 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling LogGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): free 120553643 bytes of WAL
I20260812 06:18:47.237864 29189 log_reader.cc:385] T 8bb474e7d86e49f6a1bd88d4ea87f3b8: removed 12 log segments from log reader
I20260812 06:18:47.237918 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000028 (ops 134-138)
I20260812 06:18:47.237962 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000029 (ops 139-142)
I20260812 06:18:47.237993 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000030 (ops 143-147)
I20260812 06:18:47.238026 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000031 (ops 148-152)
I20260812 06:18:47.238056 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000032 (ops 153-157)
I20260812 06:18:47.238088 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000033 (ops 158-162)
I20260812 06:18:47.238117 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000034 (ops 163-167)
I20260812 06:18:47.238147 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000035 (ops 168-172)
I20260812 06:18:47.238178 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000036 (ops 173-176)
I20260812 06:18:47.238207 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000037 (ops 177-181)
I20260812 06:18:47.238237 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000038 (ops 182-186)
I20260812 06:18:47.238267 29189 log.cc:1079] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: Deleting log segment in path: /tmp/dist-test-taskH97jIv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517251654-28651-0/minicluster-data/ts-0-root/wals/8bb474e7d86e49f6a1bd88d4ea87f3b8/wal-000000039 (ops 187-191)
I20260812 06:18:47.261619 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: LogGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:47.262102 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling UndoDeltaBlockGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): 448 bytes on disk
I20260812 06:18:47.262595 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: UndoDeltaBlockGCOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.263311 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=3.181125
I20260812 06:18:47.277863 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:47.278337 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=2.188937
I20260812 06:18:47.292596 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5137,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.293169 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:47.463058 28651 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.851s	user 1.715s	sys 0.213s
I20260812 06:18:47.514936 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.221s	user 0.147s	sys 0.070s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020849,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":15056,"lbm_reads_lt_1ms":771,"lbm_write_time_us":35937,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:18:47.515596 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=14.095187
I20260812 06:18:47.563853 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: FlushDeltaMemStoresOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.048s	user 0.035s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22407,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.564380 29307 maintenance_manager.cc:419] P af323282bcf74c9d841bce3844ffb86d: Scheduling MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8): perf score=1.000000
I20260812 06:18:47.596467 28651 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.133s	user 0.003s	sys 0.000s
I20260812 06:18:47.596998 28651 tablet_server.cc:179] TabletServer@127.27.250.193:0 shutting down...
I20260812 06:18:47.683602 29189 maintenance_manager.cc:643] P af323282bcf74c9d841bce3844ffb86d: MajorDeltaCompactionOp(8bb474e7d86e49f6a1bd88d4ea87f3b8) complete. Timing: real 0.119s	user 0.091s	sys 0.027s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":290,"lbm_read_time_us":10291,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21627,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.684317 28651 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:47.684566 28651 tablet_replica.cc:333] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d: stopping tablet replica
I20260812 06:18:47.684693 28651 raft_consensus.cc:2243] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.684852 28651 raft_consensus.cc:2272] T 8bb474e7d86e49f6a1bd88d4ea87f3b8 P af323282bcf74c9d841bce3844ffb86d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.698776 28651 tablet_server.cc:196] TabletServer@127.27.250.193:0 shutdown complete.
I20260812 06:18:47.721666 28651 master.cc:562] Master@127.27.250.254:35085 shutting down...
I20260812 06:18:47.725033 28651 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.725209 28651 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.725267 28651 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9ebf32b7f43f4973819f9bf57a6c10a7: stopping tablet replica
I20260812 06:18:47.737543 28651 master.cc:584] Master@127.27.250.254:35085 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5391 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10554 ms total)

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