[==========] 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:09.577647 21366 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.221.190:40429
I20260812 06:18:09.578677 21366 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:09.579293 21366 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:09.586086 21366 server_base.cc:1061] running on GCE node
W20260812 06:18:09.586244 21375 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:09.586189 21374 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:09.586571 21378 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:09.587121 21366 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:09.587247 21366 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:09.587293 21366 hybrid_clock.cc:648] HybridClock initialized: now 1786515489587290 us; error 0 us; skew 500 ppm
I20260812 06:18:09.589252 21366 webserver.cc:533] Webserver started at http://127.20.221.190:39489/ using document root <none> and password file <none>
I20260812 06:18:09.589849 21366 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:09.589943 21366 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:09.590234 21366 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:09.592124 21366 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/master-0-root/instance:
uuid: "7a3035a0bec54020b8f2b646ccce99af"
format_stamp: "Formatted at 2026-08-12 06:18:09 on dist-test-slave-mjjr"
I20260812 06:18:09.595721 21366 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:09.597841 21385 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:09.598838 21366 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:09.598981 21366 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/master-0-root
uuid: "7a3035a0bec54020b8f2b646ccce99af"
format_stamp: "Formatted at 2026-08-12 06:18:09 on dist-test-slave-mjjr"
I20260812 06:18:09.599093 21366 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-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:09.614854 21366 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:09.615533 21366 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:09.615746 21366 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:09.623747 21366 rpc_server.cc:307] RPC server started. Bound to: 127.20.221.190:40429
I20260812 06:18:09.623795 21463 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.221.190:40429 every 8 connection(s)
I20260812 06:18:09.625994 21465 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:09.631296 21465 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af: Bootstrap starting.
I20260812 06:18:09.633594 21465 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:09.634446 21465 log.cc:826] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:09.636181 21465 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af: No bootstrap required, opened a new log
I20260812 06:18:09.638880 21465 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a3035a0bec54020b8f2b646ccce99af" member_type: VOTER }
I20260812 06:18:09.639038 21465 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:09.639079 21465 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7a3035a0bec54020b8f2b646ccce99af, State: Initialized, Role: FOLLOWER
I20260812 06:18:09.639597 21465 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [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: "7a3035a0bec54020b8f2b646ccce99af" member_type: VOTER }
I20260812 06:18:09.639747 21465 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:09.639794 21465 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:09.639882 21465 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:09.640592 21465 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a3035a0bec54020b8f2b646ccce99af" member_type: VOTER }
I20260812 06:18:09.640970 21465 leader_election.cc:304] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [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: 7a3035a0bec54020b8f2b646ccce99af; no voters: 
I20260812 06:18:09.641269 21465 leader_election.cc:290] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:09.641396 21470 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:09.641652 21470 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 1 LEADER]: Becoming Leader. State: Replica: 7a3035a0bec54020b8f2b646ccce99af, State: Running, Role: LEADER
I20260812 06:18:09.642086 21470 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [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: "7a3035a0bec54020b8f2b646ccce99af" member_type: VOTER }
I20260812 06:18:09.642331 21465 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:09.643975 21472 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7a3035a0bec54020b8f2b646ccce99af. Latest consensus state: current_term: 1 leader_uuid: "7a3035a0bec54020b8f2b646ccce99af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a3035a0bec54020b8f2b646ccce99af" member_type: VOTER } }
I20260812 06:18:09.644109 21472 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:09.644044 21471 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7a3035a0bec54020b8f2b646ccce99af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a3035a0bec54020b8f2b646ccce99af" member_type: VOTER } }
I20260812 06:18:09.644183 21471 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:09.644541 21488 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:09.644771 21366 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:09.647163 21488 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:09.651660 21488 catalog_manager.cc:1383] Generated new cluster ID: dd286d6a947f48919093a9802ccf24c2
I20260812 06:18:09.651731 21488 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:09.664433 21488 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:09.665292 21488 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:09.688134 21488 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af: Generated new TSK 0
I20260812 06:18:09.688863 21488 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:09.710059 21366 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:09.712872 21497 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:09.713011 21498 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:09.712925 21501 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:09.713541 21366 server_base.cc:1061] running on GCE node
I20260812 06:18:09.713734 21366 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:09.713780 21366 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:09.713796 21366 hybrid_clock.cc:648] HybridClock initialized: now 1786515489713797 us; error 0 us; skew 500 ppm
I20260812 06:18:09.714926 21366 webserver.cc:533] Webserver started at http://127.20.221.129:43231/ using document root <none> and password file <none>
I20260812 06:18:09.715108 21366 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:09.715167 21366 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:09.715265 21366 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:09.715754 21366 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/instance:
uuid: "2a3eb6ee1ae742ae86d291e5dec0f3f2"
format_stamp: "Formatted at 2026-08-12 06:18:09 on dist-test-slave-mjjr"
I20260812 06:18:09.717306 21366 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:09.718374 21510 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:09.718623 21366 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:09.718700 21366 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root
uuid: "2a3eb6ee1ae742ae86d291e5dec0f3f2"
format_stamp: "Formatted at 2026-08-12 06:18:09 on dist-test-slave-mjjr"
I20260812 06:18:09.718792 21366 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-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:09.738785 21366 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:09.739296 21366 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:09.739892 21366 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:09.740814 21366 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:09.740867 21366 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:09.740940 21366 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:09.740984 21366 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:09.747454 21366 rpc_server.cc:307] RPC server started. Bound to: 127.20.221.129:39175
I20260812 06:18:09.747514 21614 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.221.129:39175 every 8 connection(s)
I20260812 06:18:09.761308 21615 heartbeater.cc:344] Connected to a master server at 127.20.221.190:40429
I20260812 06:18:09.761613 21615 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:09.762107 21615 heartbeater.cc:507] Master 127.20.221.190:40429 requested a full tablet report, sending...
I20260812 06:18:09.763860 21406 ts_manager.cc:194] Registered new tserver with Master: 2a3eb6ee1ae742ae86d291e5dec0f3f2 (127.20.221.129:39175)
I20260812 06:18:09.763993 21366 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015833929s
I20260812 06:18:09.765492 21406 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45440
I20260812 06:18:09.774322 21406 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45446:
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:09.789772 21559 tablet_service.cc:1511] Processing CreateTablet for tablet 0aa65a3ae61b4a2aa5c2dcd7950a5186 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2c65d142ec454652ab9df4733bdbfc58]), partition=
I20260812 06:18:09.790326 21559 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0aa65a3ae61b4a2aa5c2dcd7950a5186. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:09.793314 21632 tablet_bootstrap.cc:492] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Bootstrap starting.
I20260812 06:18:09.794545 21632 tablet_bootstrap.cc:654] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:09.795794 21632 tablet_bootstrap.cc:492] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: No bootstrap required, opened a new log
I20260812 06:18:09.795917 21632 ts_tablet_manager.cc:1403] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:09.796497 21632 raft_consensus.cc:359] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a3eb6ee1ae742ae86d291e5dec0f3f2" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 39175 } }
I20260812 06:18:09.796700 21632 raft_consensus.cc:385] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:09.796758 21632 raft_consensus.cc:740] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2a3eb6ee1ae742ae86d291e5dec0f3f2, State: Initialized, Role: FOLLOWER
I20260812 06:18:09.796892 21632 consensus_queue.cc:260] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [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: "2a3eb6ee1ae742ae86d291e5dec0f3f2" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 39175 } }
I20260812 06:18:09.796974 21632 raft_consensus.cc:399] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:09.797024 21632 raft_consensus.cc:493] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:09.797078 21632 raft_consensus.cc:3060] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:09.797801 21632 raft_consensus.cc:515] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a3eb6ee1ae742ae86d291e5dec0f3f2" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 39175 } }
I20260812 06:18:09.797915 21632 leader_election.cc:304] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [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: 2a3eb6ee1ae742ae86d291e5dec0f3f2; no voters: 
I20260812 06:18:09.798177 21632 leader_election.cc:290] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:09.798331 21639 raft_consensus.cc:2804] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:09.798532 21632 ts_tablet_manager.cc:1434] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:09.798628 21639 raft_consensus.cc:697] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 1 LEADER]: Becoming Leader. State: Replica: 2a3eb6ee1ae742ae86d291e5dec0f3f2, State: Running, Role: LEADER
I20260812 06:18:09.798748 21615 heartbeater.cc:499] Master 127.20.221.190:40429 was elected leader, sending a full tablet report...
I20260812 06:18:09.798785 21639 consensus_queue.cc:237] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [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: "2a3eb6ee1ae742ae86d291e5dec0f3f2" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 39175 } }
I20260812 06:18:09.801673 21406 catalog_manager.cc:5719] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2a3eb6ee1ae742ae86d291e5dec0f3f2 (127.20.221.129). New cstate: current_term: 1 leader_uuid: "2a3eb6ee1ae742ae86d291e5dec0f3f2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a3eb6ee1ae742ae86d291e5dec0f3f2" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 39175 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:09.865183 21366 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.016s	sys 0.009s
I20260812 06:18:09.998667 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushMRSOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=19.054940
I20260812 06:18:10.186201 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushMRSOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.187s	user 0.123s	sys 0.061s Metrics: {"bytes_written":13374124,"cfile_init":1,"compiler_manager_pool.queue_time_us":268,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1967,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45821,"lbm_writes_lt_1ms":783,"mutex_wait_us":152,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":172800,"thread_start_us":197,"threads_started":1,"update_count":1630}
I20260812 06:18:10.187561 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): free 20290830 bytes of WAL
I20260812 06:18:10.187938 21519 log_reader.cc:385] T 0aa65a3ae61b4a2aa5c2dcd7950a5186: removed 2 log segments from log reader
I20260812 06:18:10.188043 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000001 (ops 1-6)
I20260812 06:18:10.188113 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000002 (ops 7-10)
I20260812 06:18:10.193322 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:10.193699 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling UndoDeltaBlockGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): 16411393 bytes on disk
I20260812 06:18:10.194301 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: UndoDeltaBlockGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:18:10.194715 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:10.218819 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.024s	user 0.000s	sys 0.018s Metrics: {"bytes_written":3446259,"delete_count":0,"lbm_write_time_us":5228,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:18:10.219447 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:10.232789 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5094,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:10.233319 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:10.401912 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.168s	user 0.113s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774788,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":936,"lbm_read_time_us":11994,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29491,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"thread_start_us":430,"threads_started":5,"update_count":2500}
I20260812 06:18:10.402544 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=10.126437
I20260812 06:18:10.435840 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.033s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13121,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.436430 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:10.452153 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.016s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5865,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.452664 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:10.584681 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.132s	user 0.112s	sys 0.019s 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":928,"lbm_read_time_us":9818,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24705,"lbm_writes_lt_1ms":443,"mutex_wait_us":291,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:18:10.585179 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=10.126437
I20260812 06:18:10.633824 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.048s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16122,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:18:10.634312 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:10.645295 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3911,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.645952 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:10.775303 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.129s	user 0.101s	sys 0.028s 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":1017,"lbm_read_time_us":9385,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23963,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19840,"update_count":2000}
I20260812 06:18:10.775980 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=10.126437
I20260812 06:18:10.821457 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.045s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16761,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.821910 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:10.833046 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.011s	user 0.000s	sys 0.009s 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:10.833643 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:10.958500 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.125s	user 0.091s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":855,"lbm_read_time_us":9555,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23902,"lbm_writes_lt_1ms":443,"mutex_wait_us":304,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:18:10.958982 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=10.126437
I20260812 06:18:11.009986 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.051s	user 0.023s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18372,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.010695 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:11.021733 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.022207 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:11.164963 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.143s	user 0.094s	sys 0.048s 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":948,"lbm_read_time_us":10624,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23754,"lbm_writes_lt_1ms":443,"mutex_wait_us":357,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:11.165655 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=10.126437
I20260812 06:18:11.216100 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.050s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15939,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.216611 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:11.227795 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.228295 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:11.357879 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.129s	user 0.100s	sys 0.029s 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":193,"lbm_read_time_us":10438,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24223,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":38144,"update_count":2000}
I20260812 06:18:11.358505 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=10.126437
I20260812 06:18:11.395375 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.037s	user 0.011s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15002,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.395926 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:11.410822 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5780,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.411381 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushMRSOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:11.442435 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushMRSOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1409,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1678,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:11.443390 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): free 112692365 bytes of WAL
I20260812 06:18:11.443704 21519 log_reader.cc:385] T 0aa65a3ae61b4a2aa5c2dcd7950a5186: removed 11 log segments from log reader
I20260812 06:18:11.443768 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000003 (ops 11-15)
I20260812 06:18:11.443807 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000004 (ops 16-20)
I20260812 06:18:11.443838 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000005 (ops 21-25)
I20260812 06:18:11.443862 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000006 (ops 26-30)
I20260812 06:18:11.443892 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000007 (ops 31-35)
I20260812 06:18:11.443924 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000008 (ops 36-40)
I20260812 06:18:11.443953 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000009 (ops 41-45)
I20260812 06:18:11.443993 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000010 (ops 46-50)
I20260812 06:18:11.444022 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000011 (ops 51-55)
I20260812 06:18:11.444051 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000012 (ops 56-60)
I20260812 06:18:11.444082 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000013 (ops 61-65)
I20260812 06:18:11.470031 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.026s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:11.470486 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:11.493784 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.023s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.494240 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:11.509316 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.509931 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling UndoDeltaBlockGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): 462 bytes on disk
I20260812 06:18:11.510370 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: UndoDeltaBlockGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) 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:11.510838 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:11.690306 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.179s	user 0.109s	sys 0.059s 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":340,"lbm_read_time_us":11413,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35447,"lbm_writes_lt_1ms":643,"mutex_wait_us":68,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8192,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:18:11.690914 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=14.095187
I20260812 06:18:11.743362 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.052s	user 0.019s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20687,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.743939 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:11.756682 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.757258 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:11.919628 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.162s	user 0.116s	sys 0.040s 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":743,"lbm_read_time_us":12199,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31840,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:18:11.920338 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=14.095187
I20260812 06:18:11.977612 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.057s	user 0.038s	sys 0.010s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22899,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.978097 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:11.988646 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3907,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.989250 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:12.173296 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.184s	user 0.131s	sys 0.053s 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":215,"lbm_read_time_us":13947,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28974,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:18:12.173933 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=14.095187
I20260812 06:18:12.217497 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.043s	user 0.014s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19397,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.218122 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:12.354462 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.136s	user 0.098s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":66,"lbm_read_time_us":8886,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23447,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:18:12.355211 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=11.118625
I20260812 06:18:12.392879 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.037s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16112,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:12.393638 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:12.420782 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.027s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5500,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:18:12.421314 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:12.431846 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.432310 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:12.615384 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.183s	user 0.112s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":410,"lbm_read_time_us":10624,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27465,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:18:12.615912 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=14.095187
I20260812 06:18:12.673290 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.057s	user 0.010s	sys 0.039s Metrics: {"bytes_written":16409908,"delete_count":0,"lbm_write_time_us":23335,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.673789 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:12.685338 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.685840 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:12.859826 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.174s	user 0.107s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774695,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":932,"lbm_read_time_us":11780,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29195,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:12.860450 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=14.095187
I20260812 06:18:12.913249 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.053s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23773,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.913793 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:12.926738 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.927412 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushMRSOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:12.962464 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushMRSOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.035s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1448,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1717,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:12.963778 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): free 128867395 bytes of WAL
I20260812 06:18:12.964059 21519 log_reader.cc:385] T 0aa65a3ae61b4a2aa5c2dcd7950a5186: removed 13 log segments from log reader
I20260812 06:18:12.964146 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000014 (ops 66-70)
I20260812 06:18:12.964238 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000015 (ops 71-74)
I20260812 06:18:12.964295 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000016 (ops 75-79)
I20260812 06:18:12.964371 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000017 (ops 80-84)
I20260812 06:18:12.964418 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000018 (ops 85-89)
I20260812 06:18:12.964468 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000019 (ops 90-94)
I20260812 06:18:12.964541 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000020 (ops 95-99)
I20260812 06:18:12.964587 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000021 (ops 100-104)
I20260812 06:18:12.964636 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000022 (ops 105-108)
I20260812 06:18:12.964684 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000023 (ops 109-113)
I20260812 06:18:12.964730 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000024 (ops 114-118)
I20260812 06:18:12.964776 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000025 (ops 119-122)
I20260812 06:18:12.964824 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000026 (ops 123-127)
I20260812 06:18:12.993957 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:12.994459 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=6.157687
I20260812 06:18:13.032141 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.037s	user 0.010s	sys 0.027s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":12430,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:13.032680 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): free 8767191 bytes of WAL
I20260812 06:18:13.033012 21519 log_reader.cc:385] T 0aa65a3ae61b4a2aa5c2dcd7950a5186: removed 1 log segments from log reader
I20260812 06:18:13.033085 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000027 (ops 128-132)
I20260812 06:18:13.035434 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:13.035808 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:13.258818 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.223s	user 0.151s	sys 0.060s Metrics: {"cfile_cache_miss":723,"cfile_cache_miss_bytes":32569390,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":763,"lbm_read_time_us":16471,"lbm_reads_lt_1ms":755,"lbm_write_time_us":38517,"lbm_writes_lt_1ms":733,"mutex_wait_us":315,"peak_mem_usage":86518310,"reinsert_count":0,"spinlock_wait_cycles":10624,"thread_start_us":82,"threads_started":1,"update_count":3450}
I20260812 06:18:13.259565 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling UndoDeltaBlockGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): 492 bytes on disk
I20260812 06:18:13.260174 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: UndoDeltaBlockGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:18:13.261021 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=19.056125
I20260812 06:18:13.331314 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.070s	user 0.035s	sys 0.025s Metrics: {"bytes_written":20922561,"delete_count":0,"lbm_write_time_us":28507,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:18:13.331996 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:13.348121 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.348824 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:13.567483 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.218s	user 0.165s	sys 0.048s Metrics: {"cfile_cache_miss":642,"cfile_cache_miss_bytes":29287348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":771,"lbm_read_time_us":19018,"lbm_reads_lt_1ms":682,"lbm_write_time_us":34363,"lbm_writes_lt_1ms":653,"mutex_wait_us":24,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":3050}
I20260812 06:18:13.568334 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=17.071750
I20260812 06:18:13.635890 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.067s	user 0.032s	sys 0.026s Metrics: {"bytes_written":18748279,"delete_count":0,"lbm_write_time_us":26261,"lbm_writes_lt_1ms":460,"reinsert_count":0,"update_count":2285}
I20260812 06:18:13.636374 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=4.173312
I20260812 06:18:13.652588 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":5866711,"delete_count":0,"lbm_write_time_us":6567,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:18:13.653051 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:13.863519 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.210s	user 0.149s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877112,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":566,"lbm_read_time_us":16101,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36072,"lbm_writes_lt_1ms":643,"mutex_wait_us":97,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:18:13.867964 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=17.071750
I20260812 06:18:13.921865 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.053s	user 0.040s	sys 0.007s Metrics: {"bytes_written":19486715,"delete_count":0,"lbm_write_time_us":22958,"lbm_writes_lt_1ms":478,"reinsert_count":0,"update_count":2375}
I20260812 06:18:13.922369 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:13.933715 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.011s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1436031,"delete_count":0,"lbm_write_time_us":1448,"lbm_writes_lt_1ms":38,"reinsert_count":0,"update_count":175}
I20260812 06:18:13.934218 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:13.948027 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5213,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:13.948594 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:14.142455 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.194s	user 0.142s	sys 0.052s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877152,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":363,"lbm_read_time_us":15063,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31846,"lbm_writes_lt_1ms":643,"mutex_wait_us":48,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:18:14.143163 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=14.095187
I20260812 06:18:14.198298 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.055s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20489,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.198845 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:14.210709 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.211229 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:14.380283 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.169s	user 0.133s	sys 0.035s 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":227,"lbm_read_time_us":11702,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30045,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29696,"update_count":2500}
I20260812 06:18:14.381067 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=14.095187
I20260812 06:18:14.439414 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.058s	user 0.021s	sys 0.033s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21818,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.440207 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:14.452462 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4723,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.454378 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushMRSOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:14.493196 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushMRSOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.039s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1288,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1468,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:14.494021 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): free 123804468 bytes of WAL
I20260812 06:18:14.494297 21519 log_reader.cc:385] T 0aa65a3ae61b4a2aa5c2dcd7950a5186: removed 12 log segments from log reader
I20260812 06:18:14.494360 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000028 (ops 133-137)
I20260812 06:18:14.494400 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000029 (ops 138-142)
I20260812 06:18:14.494431 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000030 (ops 143-147)
I20260812 06:18:14.494472 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000031 (ops 148-152)
I20260812 06:18:14.494493 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000032 (ops 153-156)
I20260812 06:18:14.494515 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000033 (ops 157-161)
I20260812 06:18:14.494547 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000034 (ops 162-166)
I20260812 06:18:14.494581 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000035 (ops 167-171)
I20260812 06:18:14.494612 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000036 (ops 172-176)
I20260812 06:18:14.494642 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000037 (ops 177-181)
I20260812 06:18:14.494668 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000038 (ops 182-186)
I20260812 06:18:14.494695 21519 log.cc:1079] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/0aa65a3ae61b4a2aa5c2dcd7950a5186/wal-000000039 (ops 187-190)
I20260812 06:18:14.525286 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: LogGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:14.525766 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling UndoDeltaBlockGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): 462 bytes on disk
I20260812 06:18:14.526264 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: UndoDeltaBlockGCOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) 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:14.527051 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:14.550112 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.023s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6354,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.550627 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=2.188937
I20260812 06:18:14.561450 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4118,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.561957 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:14.748579 21366 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.883s	user 1.890s	sys 0.104s
I20260812 06:18:14.773203 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.211s	user 0.145s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15781,"lbm_reads_lt_1ms":770,"lbm_write_time_us":40226,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:18:14.773699 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=14.095187
I20260812 06:18:14.806108 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: FlushDeltaMemStoresOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.032s	user 0.020s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":15667,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.806576 21616 maintenance_manager.cc:419] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: Scheduling MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186): perf score=1.000000
I20260812 06:18:14.820992 21366 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.002s	sys 0.000s
I20260812 06:18:14.821642 21366 tablet_server.cc:179] TabletServer@127.20.221.129:0 shutting down...
I20260812 06:18:14.924074 21519 maintenance_manager.cc:643] P 2a3eb6ee1ae742ae86d291e5dec0f3f2: MajorDeltaCompactionOp(0aa65a3ae61b4a2aa5c2dcd7950a5186) complete. Timing: real 0.117s	user 0.085s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":661,"lbm_read_time_us":9494,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24700,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.924871 21366 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:14.925261 21366 tablet_replica.cc:333] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2: stopping tablet replica
I20260812 06:18:14.925513 21366 raft_consensus.cc:2243] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:14.925740 21366 raft_consensus.cc:2272] T 0aa65a3ae61b4a2aa5c2dcd7950a5186 P 2a3eb6ee1ae742ae86d291e5dec0f3f2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:14.931265 21366 tablet_server.cc:196] TabletServer@127.20.221.129:0 shutdown complete.
I20260812 06:18:14.963351 21366 master.cc:562] Master@127.20.221.190:40429 shutting down...
I20260812 06:18:14.967926 21366 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:14.968142 21366 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:14.968250 21366 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7a3035a0bec54020b8f2b646ccce99af: stopping tablet replica
I20260812 06:18:14.980652 21366 master.cc:584] Master@127.20.221.190:40429 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5491 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:15.082161 21366 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.221.190:40683
I20260812 06:18:15.082525 21366 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:15.084620 21674 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:15.084600 21669 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:15.084623 21670 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:15.084848 21366 server_base.cc:1061] running on GCE node
I20260812 06:18:15.085026 21366 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:15.085070 21366 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:15.085086 21366 hybrid_clock.cc:648] HybridClock initialized: now 1786515495085087 us; error 0 us; skew 500 ppm
I20260812 06:18:15.085971 21366 webserver.cc:533] Webserver started at http://127.20.221.190:42239/ using document root <none> and password file <none>
I20260812 06:18:15.086149 21366 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:15.086207 21366 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:15.086308 21366 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:15.086746 21366 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/master-0-root/instance:
uuid: "837f415310c3408c918a7452a911380d"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-mjjr"
I20260812 06:18:15.088563 21366 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:15.089474 21681 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:15.089723 21366 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:15.089812 21366 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/master-0-root
uuid: "837f415310c3408c918a7452a911380d"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-mjjr"
I20260812 06:18:15.089896 21366 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-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:15.098205 21366 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:15.098582 21366 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:15.102955 21366 rpc_server.cc:307] RPC server started. Bound to: 127.20.221.190:40683
I20260812 06:18:15.108949 21763 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:15.108994 21762 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.221.190:40683 every 8 connection(s)
I20260812 06:18:15.110971 21763 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d: Bootstrap starting.
I20260812 06:18:15.111861 21763 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:15.112996 21763 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d: No bootstrap required, opened a new log
I20260812 06:18:15.113417 21763 raft_consensus.cc:359] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "837f415310c3408c918a7452a911380d" member_type: VOTER }
I20260812 06:18:15.113512 21763 raft_consensus.cc:385] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:15.113535 21763 raft_consensus.cc:740] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 837f415310c3408c918a7452a911380d, State: Initialized, Role: FOLLOWER
I20260812 06:18:15.113708 21763 consensus_queue.cc:260] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [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: "837f415310c3408c918a7452a911380d" member_type: VOTER }
I20260812 06:18:15.113782 21763 raft_consensus.cc:399] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:15.113835 21763 raft_consensus.cc:493] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:15.113898 21763 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:15.114636 21763 raft_consensus.cc:515] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "837f415310c3408c918a7452a911380d" member_type: VOTER }
I20260812 06:18:15.114754 21763 leader_election.cc:304] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [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: 837f415310c3408c918a7452a911380d; no voters: 
I20260812 06:18:15.115032 21763 leader_election.cc:290] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:15.115214 21766 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:15.115422 21766 raft_consensus.cc:697] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 1 LEADER]: Becoming Leader. State: Replica: 837f415310c3408c918a7452a911380d, State: Running, Role: LEADER
I20260812 06:18:15.115554 21763 sys_catalog.cc:565] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:15.115576 21766 consensus_queue.cc:237] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [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: "837f415310c3408c918a7452a911380d" member_type: VOTER }
I20260812 06:18:15.116027 21768 sys_catalog.cc:455] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "837f415310c3408c918a7452a911380d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "837f415310c3408c918a7452a911380d" member_type: VOTER } }
I20260812 06:18:15.116065 21769 sys_catalog.cc:455] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 837f415310c3408c918a7452a911380d. Latest consensus state: current_term: 1 leader_uuid: "837f415310c3408c918a7452a911380d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "837f415310c3408c918a7452a911380d" member_type: VOTER } }
I20260812 06:18:15.116142 21769 sys_catalog.cc:458] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:15.116389 21768 sys_catalog.cc:458] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:15.116869 21772 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:15.117534 21772 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:15.117771 21366 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:15.119381 21772 catalog_manager.cc:1383] Generated new cluster ID: bd149ee8dd494016a6b6b0c5892ffb17
I20260812 06:18:15.119426 21772 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:15.133988 21772 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:15.134528 21772 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:15.140836 21772 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d: Generated new TSK 0
I20260812 06:18:15.141016 21772 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:15.150031 21366 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:15.152230 21366 server_base.cc:1061] running on GCE node
W20260812 06:18:15.152257 21798 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:15.152310 21794 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:15.152338 21795 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:15.152626 21366 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:15.152673 21366 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:15.152689 21366 hybrid_clock.cc:648] HybridClock initialized: now 1786515495152690 us; error 0 us; skew 500 ppm
I20260812 06:18:15.153510 21366 webserver.cc:533] Webserver started at http://127.20.221.129:44091/ using document root <none> and password file <none>
I20260812 06:18:15.153647 21366 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:15.153689 21366 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:15.153745 21366 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:15.154090 21366 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/instance:
uuid: "8ce8cf8247c840e78bd1a11f626d48cf"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-mjjr"
I20260812 06:18:15.155604 21366 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:15.156577 21804 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:15.156857 21366 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:15.156963 21366 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root
uuid: "8ce8cf8247c840e78bd1a11f626d48cf"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-mjjr"
I20260812 06:18:15.157058 21366 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-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:15.173769 21366 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:15.174222 21366 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:15.174568 21366 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:15.175179 21366 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:15.175240 21366 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:15.175293 21366 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:15.175329 21366 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:15.180851 21366 rpc_server.cc:307] RPC server started. Bound to: 127.20.221.129:44529
I20260812 06:18:15.180891 21905 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.221.129:44529 every 8 connection(s)
I20260812 06:18:15.188925 21907 heartbeater.cc:344] Connected to a master server at 127.20.221.190:40683
I20260812 06:18:15.189042 21907 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:15.189307 21907 heartbeater.cc:507] Master 127.20.221.190:40683 requested a full tablet report, sending...
I20260812 06:18:15.189973 21713 ts_manager.cc:194] Registered new tserver with Master: 8ce8cf8247c840e78bd1a11f626d48cf (127.20.221.129:44529)
I20260812 06:18:15.190140 21366 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008848149s
I20260812 06:18:15.190824 21713 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37686
I20260812 06:18:15.197335 21713 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37690:
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:15.206158 21843 tablet_service.cc:1511] Processing CreateTablet for tablet c2693536c4cf4643b371a9dfbd1f35c2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=53e88ddbfd524f73bd7fed8e37f78911]), partition=
I20260812 06:18:15.206488 21843 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c2693536c4cf4643b371a9dfbd1f35c2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:15.208773 21919 tablet_bootstrap.cc:492] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Bootstrap starting.
I20260812 06:18:15.209662 21919 tablet_bootstrap.cc:654] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:15.210749 21919 tablet_bootstrap.cc:492] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: No bootstrap required, opened a new log
I20260812 06:18:15.210850 21919 ts_tablet_manager.cc:1403] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:15.211330 21919 raft_consensus.cc:359] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8ce8cf8247c840e78bd1a11f626d48cf" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 44529 } }
I20260812 06:18:15.211453 21919 raft_consensus.cc:385] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:15.211508 21919 raft_consensus.cc:740] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8ce8cf8247c840e78bd1a11f626d48cf, State: Initialized, Role: FOLLOWER
I20260812 06:18:15.211696 21919 consensus_queue.cc:260] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [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: "8ce8cf8247c840e78bd1a11f626d48cf" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 44529 } }
I20260812 06:18:15.211833 21919 raft_consensus.cc:399] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:15.211891 21919 raft_consensus.cc:493] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:15.211946 21919 raft_consensus.cc:3060] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:15.212673 21919 raft_consensus.cc:515] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8ce8cf8247c840e78bd1a11f626d48cf" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 44529 } }
I20260812 06:18:15.212826 21919 leader_election.cc:304] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [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: 8ce8cf8247c840e78bd1a11f626d48cf; no voters: 
I20260812 06:18:15.213052 21919 leader_election.cc:290] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:15.213164 21924 raft_consensus.cc:2804] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:15.213388 21907 heartbeater.cc:499] Master 127.20.221.190:40683 was elected leader, sending a full tablet report...
I20260812 06:18:15.213430 21924 raft_consensus.cc:697] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 1 LEADER]: Becoming Leader. State: Replica: 8ce8cf8247c840e78bd1a11f626d48cf, State: Running, Role: LEADER
I20260812 06:18:15.213375 21919 ts_tablet_manager.cc:1434] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:15.213567 21924 consensus_queue.cc:237] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [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: "8ce8cf8247c840e78bd1a11f626d48cf" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 44529 } }
I20260812 06:18:15.215109 21713 catalog_manager.cc:5719] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf reported cstate change: term changed from 0 to 1, leader changed from <none> to 8ce8cf8247c840e78bd1a11f626d48cf (127.20.221.129). New cstate: current_term: 1 leader_uuid: "8ce8cf8247c840e78bd1a11f626d48cf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8ce8cf8247c840e78bd1a11f626d48cf" member_type: VOTER last_known_addr { host: "127.20.221.129" port: 44529 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:15.275804 21366 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.019s	sys 0.004s
I20260812 06:18:15.431895 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushMRSOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=19.054940
I20260812 06:18:15.589587 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushMRSOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.157s	user 0.123s	sys 0.032s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":335,"dirs.run_wall_time_us":852,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40279,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1450}
I20260812 06:18:15.590476 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2): free 20743880 bytes of WAL
I20260812 06:18:15.590747 21811 log_reader.cc:385] T c2693536c4cf4643b371a9dfbd1f35c2: removed 2 log segments from log reader
I20260812 06:18:15.590878 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000001 (ops 1-6)
I20260812 06:18:15.590972 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000002 (ops 7-11)
I20260812 06:18:15.595350 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:15.595765 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:15.618744 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.023s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.619167 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:15.629159 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.629542 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:15.811661 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.182s	user 0.096s	sys 0.086s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405561,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":853,"lbm_read_time_us":12279,"lbm_reads_lt_1ms":563,"lbm_write_time_us":29522,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":352,"threads_started":5,"update_count":2450}
I20260812 06:18:15.812419 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:15.873410 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.061s	user 0.034s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20875,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.874042 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:15.885147 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4431,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.885586 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:16.087527 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.202s	user 0.136s	sys 0.057s 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":307,"lbm_read_time_us":13606,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32863,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:18:16.088099 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:16.148577 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.060s	user 0.041s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20448,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.149158 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling UndoDeltaBlockGCOp(c2693536c4cf4643b371a9dfbd1f35c2): 16821645 bytes on disk
I20260812 06:18:16.149610 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: UndoDeltaBlockGCOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:16.150018 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:16.160974 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.161379 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:16.342850 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.181s	user 0.101s	sys 0.076s 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":158,"lbm_read_time_us":12969,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27546,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:16.343405 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:16.397109 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.054s	user 0.036s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21392,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.397619 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:16.419312 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.022s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4269,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.419891 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:16.605659 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.186s	user 0.132s	sys 0.053s 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":321,"lbm_read_time_us":11567,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31184,"lbm_writes_lt_1ms":543,"mutex_wait_us":116,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:16.606309 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:16.651849 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.045s	user 0.036s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18792,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.652441 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:16.668481 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5942,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.669073 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:16.856585 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.187s	user 0.116s	sys 0.066s 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":191,"lbm_read_time_us":10818,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28158,"lbm_writes_lt_1ms":543,"mutex_wait_us":97,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2500}
I20260812 06:18:16.857352 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:16.899976 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.042s	user 0.019s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19246,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.900697 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:16.917513 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.017s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.917950 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushMRSOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:16.947059 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushMRSOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.029s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":333,"dirs.run_wall_time_us":1393,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1897,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":896}
I20260812 06:18:16.947903 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2): free 120553373 bytes of WAL
I20260812 06:18:16.948239 21811 log_reader.cc:385] T c2693536c4cf4643b371a9dfbd1f35c2: removed 12 log segments from log reader
I20260812 06:18:16.948320 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000003 (ops 12-16)
I20260812 06:18:16.948369 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000004 (ops 17-20)
I20260812 06:18:16.948410 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000005 (ops 21-25)
I20260812 06:18:16.948439 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000006 (ops 26-30)
I20260812 06:18:16.948480 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000007 (ops 31-35)
I20260812 06:18:16.948516 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000008 (ops 36-40)
I20260812 06:18:16.948545 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000009 (ops 41-45)
I20260812 06:18:16.948573 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000010 (ops 46-50)
I20260812 06:18:16.948596 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000011 (ops 51-55)
I20260812 06:18:16.948618 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000012 (ops 56-60)
I20260812 06:18:16.948640 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000013 (ops 61-64)
I20260812 06:18:16.948661 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000014 (ops 65-69)
I20260812 06:18:16.976958 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:16.977802 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling UndoDeltaBlockGCOp(c2693536c4cf4643b371a9dfbd1f35c2): 472 bytes on disk
I20260812 06:18:16.978236 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: UndoDeltaBlockGCOp(c2693536c4cf4643b371a9dfbd1f35c2) 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:16.978739 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=3.181125
I20260812 06:18:16.999567 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.021s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7389,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:17.000154 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:17.010020 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.010s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3734,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:17.010655 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2): free 12017932 bytes of WAL
I20260812 06:18:17.010941 21811 log_reader.cc:385] T c2693536c4cf4643b371a9dfbd1f35c2: removed 1 log segments from log reader
I20260812 06:18:17.011003 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000015 (ops 70-74)
I20260812 06:18:17.014441 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:17.014861 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:17.262068 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.247s	user 0.146s	sys 0.097s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":672,"lbm_read_time_us":15399,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41688,"lbm_writes_lt_1ms":743,"mutex_wait_us":22,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14080,"thread_start_us":98,"threads_started":1,"update_count":3500}
I20260812 06:18:17.262876 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=18.063937
I20260812 06:18:17.330303 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.067s	user 0.036s	sys 0.027s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":29171,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:17.330744 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:17.340793 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.341235 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:17.547251 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.206s	user 0.126s	sys 0.080s 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":1098,"lbm_read_time_us":13460,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33979,"lbm_writes_lt_1ms":643,"mutex_wait_us":258,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:18:17.547906 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:17.595551 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.047s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20831,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.596110 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:17.613788 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.614384 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:17.780328 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.166s	user 0.094s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1285,"lbm_read_time_us":10844,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27129,"lbm_writes_lt_1ms":543,"mutex_wait_us":491,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:18:17.783819 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:17.837718 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.053s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":25644,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.838375 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:17.852995 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.014s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5562,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.853410 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:18.029227 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.176s	user 0.124s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1288,"lbm_read_time_us":12099,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29885,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:18:18.029920 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:18.088685 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.059s	user 0.022s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21547,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.089299 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:18.100364 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4343,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.100841 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:18.278064 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.177s	user 0.106s	sys 0.066s 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":198,"lbm_read_time_us":12040,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28003,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":63616,"update_count":2500}
I20260812 06:18:18.278726 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:18.339118 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.060s	user 0.024s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19570,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.339833 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:18.350575 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.351042 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:18.531286 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.180s	user 0.144s	sys 0.032s 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":708,"lbm_read_time_us":12905,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29783,"lbm_writes_lt_1ms":543,"mutex_wait_us":313,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:18:18.531972 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=11.118625
I20260812 06:18:18.571890 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.040s	user 0.036s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17156,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:18.572685 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:18.595875 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.023s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.596355 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:18.607262 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.607843 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushMRSOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:18.649784 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushMRSOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.042s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1240,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1872,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:18.650607 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2): free 121006454 bytes of WAL
I20260812 06:18:18.650874 21811 log_reader.cc:385] T c2693536c4cf4643b371a9dfbd1f35c2: removed 12 log segments from log reader
I20260812 06:18:18.650929 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000016 (ops 75-79)
I20260812 06:18:18.650960 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000017 (ops 80-84)
I20260812 06:18:18.651013 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000018 (ops 85-88)
I20260812 06:18:18.651062 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000019 (ops 89-93)
I20260812 06:18:18.651129 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000020 (ops 94-98)
I20260812 06:18:18.651191 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000021 (ops 99-103)
I20260812 06:18:18.651234 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000022 (ops 104-108)
I20260812 06:18:18.651273 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000023 (ops 109-113)
I20260812 06:18:18.651312 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000024 (ops 114-118)
I20260812 06:18:18.651352 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000025 (ops 119-123)
I20260812 06:18:18.651391 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000026 (ops 124-128)
I20260812 06:18:18.651433 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000027 (ops 129-133)
I20260812 06:18:18.677606 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:18.678045 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:18.700956 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.701519 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:18.712110 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3960,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.712602 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling UndoDeltaBlockGCOp(c2693536c4cf4643b371a9dfbd1f35c2): 492 bytes on disk
I20260812 06:18:18.713063 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: UndoDeltaBlockGCOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.713574 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:18.989928 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.276s	user 0.188s	sys 0.083s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":555,"lbm_read_time_us":20421,"lbm_reads_lt_1ms":775,"lbm_write_time_us":44877,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:18:18.990713 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=18.063937
I20260812 06:18:19.059019 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.068s	user 0.025s	sys 0.032s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27368,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:19.059491 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:19.070730 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.071305 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:19.276933 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.205s	user 0.122s	sys 0.083s 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":1448,"lbm_read_time_us":12681,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34472,"lbm_writes_lt_1ms":643,"mutex_wait_us":466,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":3000}
I20260812 06:18:19.277587 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:19.322109 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.044s	user 0.018s	sys 0.023s Metrics: {"bytes_written":16573999,"delete_count":0,"lbm_write_time_us":18330,"lbm_writes_lt_1ms":407,"mutex_wait_us":875,"reinsert_count":0,"update_count":2020}
I20260812 06:18:19.322646 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:19.338439 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3938558,"delete_count":0,"lbm_write_time_us":5393,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:19.339015 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:19.532250 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.193s	user 0.136s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3674,"lbm_read_time_us":12955,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34295,"lbm_writes_lt_1ms":543,"mutex_wait_us":3432,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:19.533030 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=15.087375
I20260812 06:18:19.580385 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.047s	user 0.030s	sys 0.016s Metrics: {"bytes_written":17271407,"delete_count":0,"lbm_write_time_us":21231,"lbm_writes_lt_1ms":424,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2105}
I20260812 06:18:19.581166 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:19.594705 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.013s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":3839,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:19.595244 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:19.768641 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.173s	user 0.129s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815660,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1187,"lbm_read_time_us":13431,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28885,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:18:19.769359 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:19.824323 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.055s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19724,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.824954 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:19.836136 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.836813 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:20.019251 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.182s	user 0.130s	sys 0.044s 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":775,"lbm_read_time_us":12807,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29917,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:18:20.020031 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=14.095187
I20260812 06:18:20.082962 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.063s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18158,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.083616 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=2.188937
I20260812 06:18:20.095052 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.095499 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushMRSOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:20.125039 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushMRSOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.029s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1320,"drs_written":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1559,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:20.125986 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling UndoDeltaBlockGCOp(c2693536c4cf4643b371a9dfbd1f35c2): 448 bytes on disk
I20260812 06:18:20.126372 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: UndoDeltaBlockGCOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:20.127072 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=1.000000
I20260812 06:18:20.296487 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: MajorDeltaCompactionOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.169s	user 0.118s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":10963,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28570,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:20.297230 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2): free 120553600 bytes of WAL
I20260812 06:18:20.297575 21811 log_reader.cc:385] T c2693536c4cf4643b371a9dfbd1f35c2: removed 12 log segments from log reader
I20260812 06:18:20.297699 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000028 (ops 134-138)
I20260812 06:18:20.297789 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000029 (ops 139-142)
I20260812 06:18:20.297855 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000030 (ops 143-147)
I20260812 06:18:20.297915 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000031 (ops 148-152)
I20260812 06:18:20.297971 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000032 (ops 153-156)
I20260812 06:18:20.298027 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000033 (ops 157-161)
I20260812 06:18:20.298082 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000034 (ops 162-166)
I20260812 06:18:20.298173 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000035 (ops 167-171)
I20260812 06:18:20.298233 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000036 (ops 172-176)
I20260812 06:18:20.298293 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000037 (ops 177-181)
I20260812 06:18:20.298359 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000038 (ops 182-186)
I20260812 06:18:20.298418 21811 log.cc:1079] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: Deleting log segment in path: /tmp/dist-test-taskpbrIl1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515489565350-21366-0/minicluster-data/ts-0-root/wals/c2693536c4cf4643b371a9dfbd1f35c2/wal-000000039 (ops 187-191)
I20260812 06:18:20.326141 21366 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.050s	user 1.856s	sys 0.213s
I20260812 06:18:20.326284 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: LogGCOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:20.326704 21908 maintenance_manager.cc:419] P 8ce8cf8247c840e78bd1a11f626d48cf: Scheduling FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2): perf score=18.063937
I20260812 06:18:20.359447 21366 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.033s	user 0.001s	sys 0.000s
I20260812 06:18:20.360018 21366 tablet_server.cc:179] TabletServer@127.20.221.129:0 shutting down...
I20260812 06:18:20.386044 21811 maintenance_manager.cc:643] P 8ce8cf8247c840e78bd1a11f626d48cf: FlushDeltaMemStoresOp(c2693536c4cf4643b371a9dfbd1f35c2) complete. Timing: real 0.059s	user 0.045s	sys 0.012s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26748,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:20.386615 21366 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:20.386838 21366 tablet_replica.cc:333] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf: stopping tablet replica
I20260812 06:18:20.386977 21366 raft_consensus.cc:2243] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:20.398161 21366 raft_consensus.cc:2272] T c2693536c4cf4643b371a9dfbd1f35c2 P 8ce8cf8247c840e78bd1a11f626d48cf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:20.401978 21366 tablet_server.cc:196] TabletServer@127.20.221.129:0 shutdown complete.
I20260812 06:18:20.404835 21366 master.cc:562] Master@127.20.221.190:40683 shutting down...
I20260812 06:18:20.408434 21366 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:20.408627 21366 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:20.408722 21366 tablet_replica.cc:333] T 00000000000000000000000000000000 P 837f415310c3408c918a7452a911380d: stopping tablet replica
I20260812 06:18:20.420918 21366 master.cc:584] Master@127.20.221.190:40683 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5438 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10931 ms total)

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