[==========] 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:16:40.574501 28052 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.101.62:44569
I20260812 06:16:40.575656 28052 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:16:40.576359 28052 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:40.583912 28060 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:16:40.583920 28063 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:16:40.584059 28052 server_base.cc:1061] running on GCE node
W20260812 06:16:40.584281 28059 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:40.584883 28052 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.585024 28052 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:16:40.585079 28052 hybrid_clock.cc:648] HybridClock initialized: now 1786515400585076 us; error 0 us; skew 500 ppm
I20260812 06:16:40.587100 28052 webserver.cc:533] Webserver started at http://127.27.101.62:34839/ using document root <none> and password file <none>
I20260812 06:16:40.587702 28052 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.587764 28052 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.588049 28052 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.589793 28052 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/master-0-root/instance:
uuid: "2a8ccec42dbd41c79c35560101da4418"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-w206"
I20260812 06:16:40.593478 28052 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.006s	sys 0.000s
I20260812 06:16:40.596024 28070 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:16:40.597134 28052 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:40.597275 28052 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/master-0-root
uuid: "2a8ccec42dbd41c79c35560101da4418"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-w206"
I20260812 06:16:40.597396 28052 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-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:16:40.609752 28052 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.610445 28052 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:16:40.610635 28052 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.618724 28052 rpc_server.cc:307] RPC server started. Bound to: 127.27.101.62:44569
I20260812 06:16:40.618769 28123 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.101.62:44569 every 8 connection(s)
I20260812 06:16:40.621201 28124 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:16:40.627910 28124 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418: Bootstrap starting.
I20260812 06:16:40.630491 28124 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.631547 28124 log.cc:826] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:40.633365 28124 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418: No bootstrap required, opened a new log
I20260812 06:16:40.636406 28124 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a8ccec42dbd41c79c35560101da4418" member_type: VOTER }
I20260812 06:16:40.636575 28124 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.636668 28124 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2a8ccec42dbd41c79c35560101da4418, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.637296 28124 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [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: "2a8ccec42dbd41c79c35560101da4418" member_type: VOTER }
I20260812 06:16:40.637468 28124 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.637540 28124 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.637718 28124 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.638593 28124 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a8ccec42dbd41c79c35560101da4418" member_type: VOTER }
I20260812 06:16:40.639078 28124 leader_election.cc:304] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [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: 2a8ccec42dbd41c79c35560101da4418; no voters: 
I20260812 06:16:40.639431 28124 leader_election.cc:290] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.639601 28127 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.639874 28127 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 1 LEADER]: Becoming Leader. State: Replica: 2a8ccec42dbd41c79c35560101da4418, State: Running, Role: LEADER
I20260812 06:16:40.640295 28127 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [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: "2a8ccec42dbd41c79c35560101da4418" member_type: VOTER }
I20260812 06:16:40.640532 28124 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:40.642271 28129 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2a8ccec42dbd41c79c35560101da4418" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a8ccec42dbd41c79c35560101da4418" member_type: VOTER } }
I20260812 06:16:40.642311 28130 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2a8ccec42dbd41c79c35560101da4418. Latest consensus state: current_term: 1 leader_uuid: "2a8ccec42dbd41c79c35560101da4418" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a8ccec42dbd41c79c35560101da4418" member_type: VOTER } }
I20260812 06:16:40.642411 28129 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.642410 28130 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.642781 28144 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:40.643035 28052 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:40.645016 28144 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:40.649549 28144 catalog_manager.cc:1383] Generated new cluster ID: c295b90cc34b4430b208cf33cebaae7e
I20260812 06:16:40.649623 28144 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:40.667383 28144 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:40.668643 28144 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:40.683848 28144 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418: Generated new TSK 0
I20260812 06:16:40.684718 28144 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:40.708034 28052 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:40.711233 28152 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:16:40.711277 28155 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:16:40.711406 28153 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:16:40.711323 28052 server_base.cc:1061] running on GCE node
I20260812 06:16:40.711643 28052 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.711714 28052 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:16:40.711743 28052 hybrid_clock.cc:648] HybridClock initialized: now 1786515400711742 us; error 0 us; skew 500 ppm
I20260812 06:16:40.712766 28052 webserver.cc:533] Webserver started at http://127.27.101.1:41377/ using document root <none> and password file <none>
I20260812 06:16:40.712975 28052 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.713047 28052 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.713125 28052 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.713524 28052 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/instance:
uuid: "b431408895ed406fa0c5f53009949c60"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-w206"
I20260812 06:16:40.715265 28052 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:40.716302 28161 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:16:40.716554 28052 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:40.716629 28052 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root
uuid: "b431408895ed406fa0c5f53009949c60"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-w206"
I20260812 06:16:40.716722 28052 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-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:16:40.737375 28052 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.737882 28052 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.738502 28052 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:40.739710 28052 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:40.739763 28052 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.739835 28052 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:40.739878 28052 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.747107 28052 rpc_server.cc:307] RPC server started. Bound to: 127.27.101.1:42629
I20260812 06:16:40.747131 28229 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.101.1:42629 every 8 connection(s)
I20260812 06:16:40.757409 28230 heartbeater.cc:344] Connected to a master server at 127.27.101.62:44569
I20260812 06:16:40.757718 28230 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:40.758237 28230 heartbeater.cc:507] Master 127.27.101.62:44569 requested a full tablet report, sending...
I20260812 06:16:40.759795 28087 ts_manager.cc:194] Registered new tserver with Master: b431408895ed406fa0c5f53009949c60 (127.27.101.1:42629)
I20260812 06:16:40.759941 28052 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012115886s
I20260812 06:16:40.761412 28087 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49318
I20260812 06:16:40.769773 28087 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49324:
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:16:40.785234 28192 tablet_service.cc:1511] Processing CreateTablet for tablet 108b1f2e0e394d4d82978e2728a4d6bd (DEFAULT_TABLE table=heavy-update-compaction-test [id=d74bebac5ffe412294b6068e781153af]), partition=
I20260812 06:16:40.785753 28192 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 108b1f2e0e394d4d82978e2728a4d6bd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:40.788287 28245 tablet_bootstrap.cc:492] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Bootstrap starting.
I20260812 06:16:40.789354 28245 tablet_bootstrap.cc:654] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.790931 28245 tablet_bootstrap.cc:492] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: No bootstrap required, opened a new log
I20260812 06:16:40.791090 28245 ts_tablet_manager.cc:1403] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:16:40.791567 28245 raft_consensus.cc:359] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b431408895ed406fa0c5f53009949c60" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 42629 } }
I20260812 06:16:40.791725 28245 raft_consensus.cc:385] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.791795 28245 raft_consensus.cc:740] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b431408895ed406fa0c5f53009949c60, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.791960 28245 consensus_queue.cc:260] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [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: "b431408895ed406fa0c5f53009949c60" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 42629 } }
I20260812 06:16:40.792078 28245 raft_consensus.cc:399] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.792128 28245 raft_consensus.cc:493] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.792181 28245 raft_consensus.cc:3060] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.792900 28245 raft_consensus.cc:515] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b431408895ed406fa0c5f53009949c60" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 42629 } }
I20260812 06:16:40.793051 28245 leader_election.cc:304] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [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: b431408895ed406fa0c5f53009949c60; no voters: 
I20260812 06:16:40.793303 28245 leader_election.cc:290] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.793619 28248 raft_consensus.cc:2804] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.793658 28245 ts_tablet_manager.cc:1434] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:40.793952 28248 raft_consensus.cc:697] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 1 LEADER]: Becoming Leader. State: Replica: b431408895ed406fa0c5f53009949c60, State: Running, Role: LEADER
I20260812 06:16:40.794126 28248 consensus_queue.cc:237] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [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: "b431408895ed406fa0c5f53009949c60" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 42629 } }
I20260812 06:16:40.794318 28230 heartbeater.cc:499] Master 127.27.101.62:44569 was elected leader, sending a full tablet report...
I20260812 06:16:40.796938 28087 catalog_manager.cc:5719] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 reported cstate change: term changed from 0 to 1, leader changed from <none> to b431408895ed406fa0c5f53009949c60 (127.27.101.1). New cstate: current_term: 1 leader_uuid: "b431408895ed406fa0c5f53009949c60" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b431408895ed406fa0c5f53009949c60" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 42629 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:40.871613 28052 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.029s	sys 0.005s
I20260812 06:16:40.998478 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushMRSOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=15.086190
I20260812 06:16:41.177100 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushMRSOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.178s	user 0.136s	sys 0.031s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":380,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":897,"drs_written":1,"lbm_read_time_us":120,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42984,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":28928,"thread_start_us":147,"threads_started":1,"update_count":1450}
I20260812 06:16:41.178580 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling LogGCOp(108b1f2e0e394d4d82978e2728a4d6bd): free 20743880 bytes of WAL
I20260812 06:16:41.178956 28166 log_reader.cc:385] T 108b1f2e0e394d4d82978e2728a4d6bd: removed 2 log segments from log reader
I20260812 06:16:41.179054 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000001 (ops 1-6)
I20260812 06:16:41.179122 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000002 (ops 7-11)
I20260812 06:16:41.185968 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: LogGCOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:41.186439 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling UndoDeltaBlockGCOp(108b1f2e0e394d4d82978e2728a4d6bd): 12719216 bytes on disk
I20260812 06:16:41.187165 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: UndoDeltaBlockGCOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.187641 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:41.212096 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.024s	user 0.013s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7782,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.212728 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:41.366531 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.154s	user 0.123s	sys 0.029s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1101,"lbm_read_time_us":10144,"lbm_reads_lt_1ms":450,"lbm_write_time_us":28618,"lbm_writes_lt_1ms":433,"mutex_wait_us":688,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":13184,"thread_start_us":406,"threads_started":5,"update_count":1950}
I20260812 06:16:41.367246 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=10.126437
I20260812 06:16:41.419972 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.053s	user 0.014s	sys 0.030s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20467,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:16:41.420595 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:41.438573 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.439242 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:41.573750 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.134s	user 0.121s	sys 0.013s 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":418,"lbm_read_time_us":10461,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26044,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:16:41.574411 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=10.126437
I20260812 06:16:41.621309 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.047s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16075,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.621872 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:41.633270 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.633961 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:41.771772 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.138s	user 0.109s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":377,"lbm_read_time_us":9465,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28607,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2000}
I20260812 06:16:41.772485 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=10.126437
I20260812 06:16:41.827823 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.055s	user 0.021s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19374,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.828433 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:41.840011 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.840577 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:42.010819 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.170s	user 0.113s	sys 0.046s 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":777,"lbm_read_time_us":11899,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28174,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:16:42.011664 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=10.126437
I20260812 06:16:42.061619 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.050s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20919,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.062127 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:42.073236 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.073899 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:42.211308 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.137s	user 0.085s	sys 0.052s 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":1198,"lbm_read_time_us":9817,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26773,"lbm_writes_lt_1ms":443,"mutex_wait_us":349,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:16:42.212105 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=10.126437
I20260812 06:16:42.248566 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.036s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16029,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.249101 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:42.266518 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.267158 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:42.392549 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.125s	user 0.072s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1191,"lbm_read_time_us":9642,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25853,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2000}
I20260812 06:16:42.393277 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=10.126437
I20260812 06:16:42.434015 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.041s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16018,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.434628 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:42.445973 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4184,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.446633 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:42.573936 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.127s	user 0.107s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":855,"lbm_read_time_us":10107,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23172,"lbm_writes_lt_1ms":443,"mutex_wait_us":272,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:16:42.574555 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=10.126437
I20260812 06:16:42.623207 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.048s	user 0.035s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15309,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.623793 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:42.635324 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4478,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.635794 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushMRSOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:42.685281 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushMRSOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.049s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1382,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:42.686318 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling LogGCOp(108b1f2e0e394d4d82978e2728a4d6bd): free 124257246 bytes of WAL
I20260812 06:16:42.686636 28166 log_reader.cc:385] T 108b1f2e0e394d4d82978e2728a4d6bd: removed 12 log segments from log reader
I20260812 06:16:42.686707 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000003 (ops 12-16)
I20260812 06:16:42.686745 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000004 (ops 17-21)
I20260812 06:16:42.686772 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000005 (ops 22-26)
I20260812 06:16:42.686800 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000006 (ops 27-30)
I20260812 06:16:42.686831 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000007 (ops 31-35)
I20260812 06:16:42.686865 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000008 (ops 36-40)
I20260812 06:16:42.686909 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000009 (ops 41-45)
I20260812 06:16:42.686932 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000010 (ops 46-50)
I20260812 06:16:42.686956 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000011 (ops 51-55)
I20260812 06:16:42.687008 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000012 (ops 56-60)
I20260812 06:16:42.687036 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000013 (ops 61-65)
I20260812 06:16:42.687069 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000014 (ops 66-70)
I20260812 06:16:42.716949 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: LogGCOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.030s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:16:42.717409 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling UndoDeltaBlockGCOp(108b1f2e0e394d4d82978e2728a4d6bd): 483 bytes on disk
I20260812 06:16:42.717919 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: UndoDeltaBlockGCOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.718502 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:42.735407 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.735872 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:42.748989 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4583,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.749676 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:42.978338 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.228s	user 0.160s	sys 0.063s 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":3825,"dirs.run_cpu_time_us":654,"dirs.run_wall_time_us":4341,"lbm_read_time_us":16330,"lbm_reads_lt_1ms":674,"lbm_write_time_us":40009,"lbm_writes_lt_1ms":643,"mutex_wait_us":970,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:16:42.978986 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=14.095187
I20260812 06:16:43.030639 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.051s	user 0.014s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23188,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.031339 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:43.049437 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6965,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.049969 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:43.233847 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.184s	user 0.132s	sys 0.048s 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":660,"lbm_read_time_us":13866,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31706,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:16:43.234400 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=14.095187
I20260812 06:16:43.300065 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.065s	user 0.031s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22955,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.300706 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:43.311786 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.312486 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:43.512807 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.200s	user 0.152s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1327,"lbm_read_time_us":14659,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34375,"lbm_writes_lt_1ms":543,"mutex_wait_us":982,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:43.513628 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=14.095187
I20260812 06:16:43.576504 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.063s	user 0.022s	sys 0.039s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24101,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.577090 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:43.589481 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4790,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.590060 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:43.775553 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.185s	user 0.121s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":14119,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31781,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:16:43.776194 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=14.095187
I20260812 06:16:43.831287 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.055s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20011,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.831923 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:43.857046 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.025s	user 0.011s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5921,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.857661 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:44.066934 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.209s	user 0.127s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":628,"lbm_read_time_us":13027,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34148,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:44.067662 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=14.095187
I20260812 06:16:44.123483 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.056s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24289,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.123965 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:44.134713 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.135465 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:44.315313 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.180s	user 0.121s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":11395,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35220,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:16:44.316066 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=10.126437
I20260812 06:16:44.353166 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.037s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15805,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:44.354030 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:44.370529 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.371090 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushMRSOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:44.427075 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushMRSOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.056s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":1508,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1966,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":4480}
I20260812 06:16:44.427891 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling LogGCOp(108b1f2e0e394d4d82978e2728a4d6bd): free 129320520 bytes of WAL
I20260812 06:16:44.428128 28166 log_reader.cc:385] T 108b1f2e0e394d4d82978e2728a4d6bd: removed 13 log segments from log reader
I20260812 06:16:44.428171 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000015 (ops 71-75)
I20260812 06:16:44.428201 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000016 (ops 76-80)
I20260812 06:16:44.428328 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000017 (ops 81-85)
I20260812 06:16:44.428387 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000018 (ops 86-90)
I20260812 06:16:44.428426 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000019 (ops 91-95)
I20260812 06:16:44.428483 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000020 (ops 96-100)
I20260812 06:16:44.428521 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000021 (ops 101-104)
I20260812 06:16:44.428560 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000022 (ops 105-109)
I20260812 06:16:44.428601 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000023 (ops 110-114)
I20260812 06:16:44.428642 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000024 (ops 115-119)
I20260812 06:16:44.428681 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000025 (ops 120-124)
I20260812 06:16:44.428725 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000026 (ops 125-128)
I20260812 06:16:44.428764 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000027 (ops 129-133)
I20260812 06:16:44.457960 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: LogGCOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:44.458354 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=6.157687
I20260812 06:16:44.493177 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":11433,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:44.493811 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling LogGCOp(108b1f2e0e394d4d82978e2728a4d6bd): free 12017954 bytes of WAL
I20260812 06:16:44.494064 28166 log_reader.cc:385] T 108b1f2e0e394d4d82978e2728a4d6bd: removed 1 log segments from log reader
I20260812 06:16:44.494109 28166 log.cc:1079] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/108b1f2e0e394d4d82978e2728a4d6bd/wal-000000028 (ops 134-138)
I20260812 06:16:44.496814 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: LogGCOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:44.497190 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:44.508383 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.508869 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:44.757510 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.248s	user 0.153s	sys 0.092s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":623,"lbm_read_time_us":18912,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39456,"lbm_writes_lt_1ms":743,"mutex_wait_us":56,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":112,"threads_started":1,"update_count":3500}
I20260812 06:16:44.758167 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling UndoDeltaBlockGCOp(108b1f2e0e394d4d82978e2728a4d6bd): 493 bytes on disk
I20260812 06:16:44.758719 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: UndoDeltaBlockGCOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.761767 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=17.071750
I20260812 06:16:44.830334 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.068s	user 0.028s	sys 0.027s Metrics: {"bytes_written":19076469,"delete_count":0,"lbm_write_time_us":26561,"lbm_writes_lt_1ms":468,"reinsert_count":0,"update_count":2325}
I20260812 06:16:44.830920 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=4.173312
I20260812 06:16:44.849815 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.019s	user 0.015s	sys 0.001s Metrics: {"bytes_written":5538517,"delete_count":0,"lbm_write_time_us":7427,"lbm_writes_lt_1ms":138,"reinsert_count":0,"update_count":675}
I20260812 06:16:44.850389 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:45.081558 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.231s	user 0.167s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877108,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":16785,"lbm_reads_lt_1ms":672,"lbm_write_time_us":41017,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":3000}
I20260812 06:16:45.082466 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=18.063937
I20260812 06:16:45.155965 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.073s	user 0.034s	sys 0.027s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28666,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:45.156592 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:45.171905 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.172544 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:45.440223 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: MajorDeltaCompactionOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.267s	user 0.151s	sys 0.061s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":326,"lbm_read_time_us":14689,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35508,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":3000}
I20260812 06:16:45.440996 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=20.048312
I20260812 06:16:45.529093 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.088s	user 0.047s	sys 0.020s Metrics: {"bytes_written":22071231,"delete_count":0,"lbm_write_time_us":30687,"lbm_writes_lt_1ms":541,"reinsert_count":0,"update_count":2690}
I20260812 06:16:45.530019 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=5.165500
I20260812 06:16:45.622596 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.092s	user 0.017s	sys 0.001s Metrics: {"bytes_written":6646165,"delete_count":0,"lbm_write_time_us":7773,"lbm_writes_lt_1ms":165,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":810}
I20260812 06:16:45.623440 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=6.157687
I20260812 06:16:45.719242 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.096s	user 0.018s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9475,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:45.720150 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=7.149875
I20260812 06:16:45.823774 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.103s	user 0.007s	sys 0.016s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10127,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:45.824422 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=8.142062
I20260812 06:16:45.929669 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.105s	user 0.020s	sys 0.004s Metrics: {"bytes_written":10256332,"delete_count":0,"lbm_write_time_us":10455,"lbm_writes_lt_1ms":253,"reinsert_count":0,"update_count":1250}
I20260812 06:16:45.930372 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=8.142062
I20260812 06:16:46.033667 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.103s	user 0.022s	sys 0.011s Metrics: {"bytes_written":9846053,"delete_count":0,"lbm_write_time_us":15106,"lbm_writes_lt_1ms":243,"reinsert_count":0,"update_count":1200}
I20260812 06:16:46.034325 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=6.157687
I20260812 06:16:46.077649 28052 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.206s	user 1.835s	sys 0.196s
I20260812 06:16:46.138402 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.104s	user 0.020s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10255,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:46.139138 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=2.188937
I20260812 06:16:46.238456 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushDeltaMemStoresOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.099s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5435,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.239354 28231 maintenance_manager.cc:419] P b431408895ed406fa0c5f53009949c60: Scheduling FlushMRSOp(108b1f2e0e394d4d82978e2728a4d6bd): perf score=1.000000
I20260812 06:16:46.271087 28052 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.193s	user 0.005s	sys 0.000s
I20260812 06:16:46.271729 28052 tablet_server.cc:179] TabletServer@127.27.101.1:0 shutting down...
I20260812 06:16:46.345679 28166 maintenance_manager.cc:643] P b431408895ed406fa0c5f53009949c60: FlushMRSOp(108b1f2e0e394d4d82978e2728a4d6bd) complete. Timing: real 0.106s	user 0.030s	sys 0.002s Metrics: {"bytes_written":1357578,"cfile_init":1,"dirs.queue_time_us":225,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2627,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33,"thread_start_us":81,"threads_started":1}
I20260812 06:16:46.346688 28052 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:46.347234 28052 tablet_replica.cc:333] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60: stopping tablet replica
I20260812 06:16:46.347486 28052 raft_consensus.cc:2243] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:46.347739 28052 raft_consensus.cc:2272] T 108b1f2e0e394d4d82978e2728a4d6bd P b431408895ed406fa0c5f53009949c60 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:46.363991 28052 tablet_server.cc:196] TabletServer@127.27.101.1:0 shutdown complete.
I20260812 06:16:46.369195 28052 master.cc:562] Master@127.27.101.62:44569 shutting down...
I20260812 06:16:46.373245 28052 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:46.373471 28052 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:46.373562 28052 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2a8ccec42dbd41c79c35560101da4418: stopping tablet replica
I20260812 06:16:46.386756 28052 master.cc:584] Master@127.27.101.62:44569 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5932 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:46.519124 28052 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.101.62:40237
I20260812 06:16:46.519591 28052 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:46.522390 28266 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:16:46.522511 28267 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:16:46.522619 28052 server_base.cc:1061] running on GCE node
W20260812 06:16:46.522390 28270 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:16:46.522951 28052 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:46.523061 28052 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:16:46.523119 28052 hybrid_clock.cc:648] HybridClock initialized: now 1786515406523118 us; error 0 us; skew 500 ppm
I20260812 06:16:46.524212 28052 webserver.cc:533] Webserver started at http://127.27.101.62:35341/ using document root <none> and password file <none>
I20260812 06:16:46.524463 28052 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:46.524534 28052 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:46.524631 28052 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:46.525115 28052 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/master-0-root/instance:
uuid: "2bde05b83ea44875a94b366a43d91f64"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-w206"
I20260812 06:16:46.526959 28052 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:46.528219 28275 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:16:46.528584 28052 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:46.528687 28052 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/master-0-root
uuid: "2bde05b83ea44875a94b366a43d91f64"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-w206"
I20260812 06:16:46.528781 28052 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-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:16:46.544481 28052 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:46.544997 28052 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:46.550346 28052 rpc_server.cc:307] RPC server started. Bound to: 127.27.101.62:40237
I20260812 06:16:46.552047 28334 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.101.62:40237 every 8 connection(s)
I20260812 06:16:46.558408 28335 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:16:46.560601 28335 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64: Bootstrap starting.
I20260812 06:16:46.561453 28335 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:46.562687 28335 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64: No bootstrap required, opened a new log
I20260812 06:16:46.563103 28335 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2bde05b83ea44875a94b366a43d91f64" member_type: VOTER }
I20260812 06:16:46.563191 28335 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:46.563213 28335 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2bde05b83ea44875a94b366a43d91f64, State: Initialized, Role: FOLLOWER
I20260812 06:16:46.563387 28335 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [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: "2bde05b83ea44875a94b366a43d91f64" member_type: VOTER }
I20260812 06:16:46.563484 28335 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:46.563510 28335 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:46.563541 28335 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:46.641453 28335 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2bde05b83ea44875a94b366a43d91f64" member_type: VOTER }
I20260812 06:16:46.641779 28335 leader_election.cc:304] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [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: 2bde05b83ea44875a94b366a43d91f64; no voters: 
I20260812 06:16:46.642088 28335 leader_election.cc:290] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:46.642310 28339 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:46.642643 28339 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 1 LEADER]: Becoming Leader. State: Replica: 2bde05b83ea44875a94b366a43d91f64, State: Running, Role: LEADER
I20260812 06:16:46.642809 28335 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:46.642920 28339 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [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: "2bde05b83ea44875a94b366a43d91f64" member_type: VOTER }
I20260812 06:16:46.643942 28342 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2bde05b83ea44875a94b366a43d91f64. Latest consensus state: current_term: 1 leader_uuid: "2bde05b83ea44875a94b366a43d91f64" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2bde05b83ea44875a94b366a43d91f64" member_type: VOTER } }
I20260812 06:16:46.643958 28340 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2bde05b83ea44875a94b366a43d91f64" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2bde05b83ea44875a94b366a43d91f64" member_type: VOTER } }
I20260812 06:16:46.644070 28342 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:46.644084 28340 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:46.644565 28352 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:46.645901 28352 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:46.646158 28052 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:46.648451 28352 catalog_manager.cc:1383] Generated new cluster ID: 16e03ab58e654843bcc8dce57eeb69d2
I20260812 06:16:46.648528 28352 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:46.666736 28352 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:46.667505 28352 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:46.676712 28352 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64: Generated new TSK 0
I20260812 06:16:46.676975 28352 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:46.678907 28052 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:46.681027 28362 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:16:46.681111 28361 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:16:46.681082 28364 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:16:46.681329 28052 server_base.cc:1061] running on GCE node
I20260812 06:16:46.681555 28052 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:46.681630 28052 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:16:46.681664 28052 hybrid_clock.cc:648] HybridClock initialized: now 1786515406681664 us; error 0 us; skew 500 ppm
I20260812 06:16:46.682777 28052 webserver.cc:533] Webserver started at http://127.27.101.1:44287/ using document root <none> and password file <none>
I20260812 06:16:46.683033 28052 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:46.683122 28052 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:46.683211 28052 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:46.683691 28052 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/instance:
uuid: "9483f406302d4eddbd466259f38b8d7c"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-w206"
I20260812 06:16:46.685470 28052 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:46.686712 28372 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:16:46.687072 28052 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:46.687157 28052 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root
uuid: "9483f406302d4eddbd466259f38b8d7c"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-w206"
I20260812 06:16:46.687230 28052 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-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:16:46.696805 28052 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:46.697244 28052 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:46.697567 28052 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:46.698132 28052 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:46.698173 28052 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.698211 28052 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:46.698272 28052 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.703274 28052 rpc_server.cc:307] RPC server started. Bound to: 127.27.101.1:45137
I20260812 06:16:46.703374 28446 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.101.1:45137 every 8 connection(s)
I20260812 06:16:46.712889 28447 heartbeater.cc:344] Connected to a master server at 127.27.101.62:40237
I20260812 06:16:46.713073 28447 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:46.713358 28447 heartbeater.cc:507] Master 127.27.101.62:40237 requested a full tablet report, sending...
I20260812 06:16:46.714622 28295 ts_manager.cc:194] Registered new tserver with Master: 9483f406302d4eddbd466259f38b8d7c (127.27.101.1:45137)
I20260812 06:16:46.715036 28052 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011267998s
I20260812 06:16:46.715588 28295 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54178
I20260812 06:16:46.724380 28295 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54188:
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:16:46.734180 28402 tablet_service.cc:1511] Processing CreateTablet for tablet a81050cf4a934af29c955d23e598ceff (DEFAULT_TABLE table=heavy-update-compaction-test [id=301d1f185fdd43a99c5f549e51772a9e]), partition=
I20260812 06:16:46.734505 28402 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a81050cf4a934af29c955d23e598ceff. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:46.736857 28459 tablet_bootstrap.cc:492] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Bootstrap starting.
I20260812 06:16:46.737798 28459 tablet_bootstrap.cc:654] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:46.739079 28459 tablet_bootstrap.cc:492] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: No bootstrap required, opened a new log
I20260812 06:16:46.739190 28459 ts_tablet_manager.cc:1403] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:46.739635 28459 raft_consensus.cc:359] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9483f406302d4eddbd466259f38b8d7c" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 45137 } }
I20260812 06:16:46.739769 28459 raft_consensus.cc:385] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:46.739814 28459 raft_consensus.cc:740] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9483f406302d4eddbd466259f38b8d7c, State: Initialized, Role: FOLLOWER
I20260812 06:16:46.739943 28459 consensus_queue.cc:260] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [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: "9483f406302d4eddbd466259f38b8d7c" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 45137 } }
I20260812 06:16:46.740005 28459 raft_consensus.cc:399] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:46.740028 28459 raft_consensus.cc:493] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:46.740063 28459 raft_consensus.cc:3060] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:46.744931 28459 raft_consensus.cc:515] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9483f406302d4eddbd466259f38b8d7c" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 45137 } }
I20260812 06:16:46.745155 28459 leader_election.cc:304] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [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: 9483f406302d4eddbd466259f38b8d7c; no voters: 
I20260812 06:16:46.745440 28459 leader_election.cc:290] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:46.745594 28461 raft_consensus.cc:2804] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:46.745824 28447 heartbeater.cc:499] Master 127.27.101.62:40237 was elected leader, sending a full tablet report...
I20260812 06:16:46.745903 28461 raft_consensus.cc:697] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 1 LEADER]: Becoming Leader. State: Replica: 9483f406302d4eddbd466259f38b8d7c, State: Running, Role: LEADER
I20260812 06:16:46.745808 28459 ts_tablet_manager.cc:1434] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Time spent starting tablet: real 0.007s	user 0.003s	sys 0.000s
I20260812 06:16:46.746151 28461 consensus_queue.cc:237] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [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: "9483f406302d4eddbd466259f38b8d7c" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 45137 } }
I20260812 06:16:46.748013 28295 catalog_manager.cc:5719] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c reported cstate change: term changed from 0 to 1, leader changed from <none> to 9483f406302d4eddbd466259f38b8d7c (127.27.101.1). New cstate: current_term: 1 leader_uuid: "9483f406302d4eddbd466259f38b8d7c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9483f406302d4eddbd466259f38b8d7c" member_type: VOTER last_known_addr { host: "127.27.101.1" port: 45137 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:46.813628 28052 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.006s	sys 0.018s
I20260812 06:16:46.954444 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushMRSOp(a81050cf4a934af29c955d23e598ceff): perf score=15.086190
I20260812 06:16:47.208043 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushMRSOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.253s	user 0.113s	sys 0.055s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":284,"dirs.run_wall_time_us":56952,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45634,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":654,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1500}
I20260812 06:16:47.209190 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling LogGCOp(a81050cf4a934af29c955d23e598ceff): free 11976772 bytes of WAL
I20260812 06:16:47.209451 28377 log_reader.cc:385] T a81050cf4a934af29c955d23e598ceff: removed 1 log segments from log reader
I20260812 06:16:47.209520 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000001 (ops 1-6)
I20260812 06:16:47.213200 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: LogGCOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:47.213730 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=10.126437
I20260812 06:16:47.298398 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.084s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15444,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.299074 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling UndoDeltaBlockGCOp(a81050cf4a934af29c955d23e598ceff): 12308959 bytes on disk
I20260812 06:16:47.299571 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: UndoDeltaBlockGCOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.300132 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=6.157687
I20260812 06:16:47.398510 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.098s	user 0.014s	sys 0.006s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8954,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.399179 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=6.157687
I20260812 06:16:47.502192 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.103s	user 0.017s	sys 0.014s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13421,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.502920 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=6.157687
I20260812 06:16:47.610687 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.107s	user 0.013s	sys 0.021s Metrics: {"bytes_written":8246102,"delete_count":0,"lbm_write_time_us":13685,"lbm_writes_lt_1ms":204,"reinsert_count":0,"update_count":1005}
I20260812 06:16:47.611351 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=7.149875
I20260812 06:16:47.707700 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.096s	user 0.022s	sys 0.012s Metrics: {"bytes_written":8574300,"delete_count":0,"lbm_write_time_us":14124,"lbm_writes_lt_1ms":212,"reinsert_count":0,"update_count":1045}
I20260812 06:16:47.708456 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=6.157687
I20260812 06:16:47.808169 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.099s	user 0.014s	sys 0.012s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":10965,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:47.809038 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=7.149875
I20260812 06:16:47.904604 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.095s	user 0.018s	sys 0.004s Metrics: {"bytes_written":8615322,"delete_count":0,"lbm_write_time_us":10207,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:47.905207 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=6.157687
I20260812 06:16:47.930874 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.025s	user 0.013s	sys 0.010s Metrics: {"bytes_written":8328152,"delete_count":0,"lbm_write_time_us":11063,"lbm_writes_lt_1ms":206,"reinsert_count":0,"update_count":1015}
I20260812 06:16:47.931412 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=2.188937
I20260812 06:16:47.978152 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.047s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":4322,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:16:47.978751 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=2.188937
I20260812 06:16:47.997663 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.998407 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff): perf score=1.000000
I20260812 06:16:48.654217 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.656s	user 0.421s	sys 0.229s Metrics: {"cfile_cache_miss":2241,"cfile_cache_miss_bytes":94475799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":11,"delta_iterators_relevant":11,"dirs.queue_time_us":242,"lbm_read_time_us":49469,"lbm_reads_lt_1ms":2277,"lbm_write_time_us":119402,"lbm_writes_lt_1ms":2245,"peak_mem_usage":274367624,"reinsert_count":0,"spinlock_wait_cycles":42752,"thread_start_us":377,"threads_started":6,"update_count":11000}
I20260812 06:16:48.654846 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=46.837375
I20260812 06:16:48.832849 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.178s	user 0.093s	sys 0.083s Metrics: {"bytes_written":49639449,"delete_count":0,"lbm_write_time_us":76535,"lbm_writes_lt_1ms":1213,"reinsert_count":0,"update_count":6050}
I20260812 06:16:48.833570 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=10.126437
I20260812 06:16:48.881582 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.048s	user 0.031s	sys 0.007s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":17974,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:48.882251 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=2.188937
I20260812 06:16:48.950011 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.067s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.950640 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=3.181125
I20260812 06:16:48.980571 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.030s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4961,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:48.981144 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=2.188937
I20260812 06:16:48.991173 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3611,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.991811 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushMRSOp(a81050cf4a934af29c955d23e598ceff): perf score=1.000000
I20260812 06:16:49.028452 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushMRSOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.036s	user 0.032s	sys 0.003s Metrics: {"bytes_written":1644367,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1380,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2162,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":40}
I20260812 06:16:49.029495 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling LogGCOp(a81050cf4a934af29c955d23e598ceff): free 162576557 bytes of WAL
I20260812 06:16:49.029770 28377 log_reader.cc:385] T a81050cf4a934af29c955d23e598ceff: removed 16 log segments from log reader
I20260812 06:16:49.029841 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000002 (ops 7-11)
I20260812 06:16:49.029883 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000003 (ops 12-16)
I20260812 06:16:49.029919 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000004 (ops 17-21)
I20260812 06:16:49.029955 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000005 (ops 22-26)
I20260812 06:16:49.029992 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000006 (ops 27-31)
I20260812 06:16:49.030048 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000007 (ops 32-36)
I20260812 06:16:49.030112 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000008 (ops 37-41)
I20260812 06:16:49.030154 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000009 (ops 42-46)
I20260812 06:16:49.030194 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000010 (ops 47-51)
I20260812 06:16:49.030231 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000011 (ops 52-56)
I20260812 06:16:49.030268 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000012 (ops 57-61)
I20260812 06:16:49.030339 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000013 (ops 62-66)
I20260812 06:16:49.030380 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000014 (ops 67-71)
I20260812 06:16:49.030452 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000015 (ops 72-76)
I20260812 06:16:49.030514 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000016 (ops 77-80)
I20260812 06:16:49.030576 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000017 (ops 81-85)
I20260812 06:16:49.069845 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: LogGCOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.040s	user 0.000s	sys 0.037s Metrics: {}
I20260812 06:16:49.070535 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=5.165500
I20260812 06:16:49.090103 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.019s	user 0.002s	sys 0.015s Metrics: {"bytes_written":6358991,"delete_count":0,"lbm_write_time_us":8414,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:16:49.090788 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling UndoDeltaBlockGCOp(a81050cf4a934af29c955d23e598ceff): 583 bytes on disk
I20260812 06:16:49.091357 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: UndoDeltaBlockGCOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:16:49.092146 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=1.000000
I20260812 06:16:49.101118 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":3394,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:16:49.101742 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff): perf score=1.000000
I20260812 06:16:49.641494 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.540s	user 0.339s	sys 0.192s Metrics: {"cfile_cache_miss":2037,"cfile_cache_miss_bytes":86270445,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":7,"delta_iterators_relevant":7,"dirs.queue_time_us":696,"lbm_read_time_us":37306,"lbm_reads_lt_1ms":2077,"lbm_write_time_us":103553,"lbm_writes_lt_1ms":2045,"mutex_wait_us":24,"peak_mem_usage":249514480,"reinsert_count":0,"spinlock_wait_cycles":41728,"thread_start_us":449,"threads_started":7,"update_count":10000}
I20260812 06:16:49.642205 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=41.876437
I20260812 06:16:49.918140 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.276s	user 0.075s	sys 0.060s Metrics: {"bytes_written":45126790,"delete_count":0,"lbm_write_time_us":60563,"lbm_writes_lt_1ms":1103,"reinsert_count":0,"update_count":5500}
I20260812 06:16:49.918850 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=19.056125
I20260812 06:16:49.981961 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.063s	user 0.045s	sys 0.015s Metrics: {"bytes_written":20922555,"delete_count":0,"lbm_write_time_us":28894,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:16:49.982537 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=2.188937
I20260812 06:16:50.006408 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.024s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4630,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.007066 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=2.188937
I20260812 06:16:50.017629 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:50.018199 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff): perf score=1.000000
I20260812 06:16:50.518692 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.500s	user 0.337s	sys 0.161s Metrics: {"cfile_cache_miss":1834,"cfile_cache_miss_bytes":78065310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":816,"lbm_read_time_us":37683,"lbm_reads_lt_1ms":1874,"lbm_write_time_us":95382,"lbm_writes_lt_1ms":1845,"peak_mem_usage":224661336,"reinsert_count":0,"spinlock_wait_cycles":17408,"thread_start_us":473,"threads_started":6,"update_count":9000}
I20260812 06:16:50.519268 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=37.907687
I20260812 06:16:50.691911 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.172s	user 0.081s	sys 0.074s Metrics: {"bytes_written":41024375,"delete_count":0,"lbm_write_time_us":63052,"lbm_writes_lt_1ms":1003,"reinsert_count":0,"update_count":5000}
I20260812 06:16:50.692575 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=10.126437
I20260812 06:16:50.732867 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.040s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17332,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.733386 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushMRSOp(a81050cf4a934af29c955d23e598ceff): perf score=1.000000
I20260812 06:16:50.789734 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushMRSOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.056s	user 0.034s	sys 0.004s Metrics: {"bytes_written":1398558,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1760,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1938,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":34}
I20260812 06:16:50.790518 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling LogGCOp(a81050cf4a934af29c955d23e598ceff): free 145042418 bytes of WAL
I20260812 06:16:50.790824 28377 log_reader.cc:385] T a81050cf4a934af29c955d23e598ceff: removed 14 log segments from log reader
I20260812 06:16:50.790885 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000018 (ops 86-90)
I20260812 06:16:50.790946 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000019 (ops 91-94)
I20260812 06:16:50.791030 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000020 (ops 95-99)
I20260812 06:16:50.791081 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000021 (ops 100-104)
I20260812 06:16:50.791159 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000022 (ops 105-109)
I20260812 06:16:50.791234 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000023 (ops 110-114)
I20260812 06:16:50.791280 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000024 (ops 115-119)
I20260812 06:16:50.791347 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000025 (ops 120-124)
I20260812 06:16:50.791388 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000026 (ops 125-129)
I20260812 06:16:50.791431 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000027 (ops 130-134)
I20260812 06:16:50.791482 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000028 (ops 135-139)
I20260812 06:16:50.791527 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000029 (ops 140-144)
I20260812 06:16:50.791574 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000030 (ops 145-149)
I20260812 06:16:50.791617 28377 log.cc:1079] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: Deleting log segment in path: /tmp/dist-test-task4MHEKa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400563424-28052-0/minicluster-data/ts-0-root/wals/a81050cf4a934af29c955d23e598ceff/wal-000000031 (ops 150-154)
I20260812 06:16:50.827982 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: LogGCOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.037s	user 0.000s	sys 0.036s Metrics: {}
I20260812 06:16:50.829046 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=10.126437
I20260812 06:16:50.881795 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.052s	user 0.014s	sys 0.021s Metrics: {"bytes_written":11569058,"delete_count":0,"lbm_write_time_us":17239,"lbm_writes_lt_1ms":285,"reinsert_count":0,"update_count":1410}
I20260812 06:16:50.882376 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling UndoDeltaBlockGCOp(a81050cf4a934af29c955d23e598ceff): 518 bytes on disk
I20260812 06:16:50.882850 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: UndoDeltaBlockGCOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:16:50.883438 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=3.181125
I20260812 06:16:50.899698 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.016s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4841098,"delete_count":0,"lbm_write_time_us":6424,"lbm_writes_lt_1ms":121,"reinsert_count":0,"update_count":590}
I20260812 06:16:50.900372 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff): perf score=1.000000
I20260812 06:16:51.421875 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.521s	user 0.313s	sys 0.204s Metrics: {"cfile_cache_miss":1734,"cfile_cache_miss_bytes":73962915,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":741,"lbm_read_time_us":38118,"lbm_reads_lt_1ms":1774,"lbm_write_time_us":92533,"lbm_writes_lt_1ms":1745,"mutex_wait_us":24,"peak_mem_usage":212234764,"reinsert_count":0,"spinlock_wait_cycles":14592,"thread_start_us":546,"threads_started":7,"update_count":8500}
I20260812 06:16:51.422706 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=37.907687
I20260812 06:16:51.664474 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.241s	user 0.080s	sys 0.056s Metrics: {"bytes_written":41024371,"delete_count":0,"lbm_write_time_us":52689,"lbm_writes_lt_1ms":1003,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":5000}
I20260812 06:16:51.665274 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=14.095187
I20260812 06:16:51.717021 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.052s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":23407,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.717857 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff): perf score=2.188937
I20260812 06:16:51.736265 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: FlushDeltaMemStoresOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5963,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.736882 28448 maintenance_manager.cc:419] P 9483f406302d4eddbd466259f38b8d7c: Scheduling MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff): perf score=1.000000
I20260812 06:16:51.961767 28052 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.148s	user 1.852s	sys 0.081s
I20260812 06:16:52.120117 28052 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.158s	user 0.002s	sys 0.000s
I20260812 06:16:52.120711 28052 tablet_server.cc:179] TabletServer@127.27.101.1:0 shutting down...
I20260812 06:16:52.156075 28377 maintenance_manager.cc:643] P 9483f406302d4eddbd466259f38b8d7c: MajorDeltaCompactionOp(a81050cf4a934af29c955d23e598ceff) complete. Timing: real 0.419s	user 0.248s	sys 0.171s Metrics: {"cfile_cache_miss":1533,"cfile_cache_miss_bytes":65757958,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1457,"lbm_read_time_us":30724,"lbm_reads_lt_1ms":1565,"lbm_write_time_us":73271,"lbm_writes_lt_1ms":1545,"mutex_wait_us":108,"peak_mem_usage":187381620,"reinsert_count":0,"spinlock_wait_cycles":19456,"thread_start_us":453,"threads_started":6,"update_count":7500}
I20260812 06:16:52.156896 28052 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:52.157182 28052 tablet_replica.cc:333] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c: stopping tablet replica
I20260812 06:16:52.157342 28052 raft_consensus.cc:2243] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:52.157599 28052 raft_consensus.cc:2272] T a81050cf4a934af29c955d23e598ceff P 9483f406302d4eddbd466259f38b8d7c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:52.166669 28052 tablet_server.cc:196] TabletServer@127.27.101.1:0 shutdown complete.
I20260812 06:16:52.348274 28052 master.cc:562] Master@127.27.101.62:40237 shutting down...
I20260812 06:16:52.352516 28052 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:52.352761 28052 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:52.352885 28052 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2bde05b83ea44875a94b366a43d91f64: stopping tablet replica
I20260812 06:16:52.365757 28052 master.cc:584] Master@127.27.101.62:40237 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5972 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11905 ms total)

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