[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:34.243000  9632 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.104.62:36591
I20260812 06:19:34.244068  9632 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:34.244673  9632 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:34.250980  9637 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:34.251075  9641 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:34.251379  9638 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:34.251382  9632 server_base.cc:1061] running on GCE node
I20260812 06:19:34.251995  9632 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:34.252148  9632 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:34.252199  9632 hybrid_clock.cc:648] HybridClock initialized: now 1786515574252196 us; error 0 us; skew 500 ppm
I20260812 06:19:34.254371  9632 webserver.cc:533] Webserver started at http://127.9.104.62:44905/ using document root <none> and password file <none>
I20260812 06:19:34.254951  9632 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:34.255061  9632 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:34.255311  9632 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:34.257000  9632 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/master-0-root/instance:
uuid: "691159fee7df4e04a0ec3754d5cf42aa"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-wl2h"
I20260812 06:19:34.260725  9632 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.005s
I20260812 06:19:34.262952  9647 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:34.264016  9632 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:34.264163  9632 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/master-0-root
uuid: "691159fee7df4e04a0ec3754d5cf42aa"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-wl2h"
I20260812 06:19:34.264286  9632 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:34.277653  9632 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:34.278398  9632 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:34.278622  9632 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:34.287528  9706 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.104.62:36591 every 8 connection(s)
I20260812 06:19:34.287525  9632 rpc_server.cc:307] RPC server started. Bound to: 127.9.104.62:36591
I20260812 06:19:34.289884  9707 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:34.295456  9707 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa: Bootstrap starting.
I20260812 06:19:34.297925  9707 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:34.298806  9707 log.cc:826] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:34.300599  9707 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa: No bootstrap required, opened a new log
I20260812 06:19:34.303409  9707 raft_consensus.cc:359] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "691159fee7df4e04a0ec3754d5cf42aa" member_type: VOTER }
I20260812 06:19:34.303586  9707 raft_consensus.cc:385] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:34.303625  9707 raft_consensus.cc:740] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 691159fee7df4e04a0ec3754d5cf42aa, State: Initialized, Role: FOLLOWER
I20260812 06:19:34.304184  9707 consensus_queue.cc:260] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [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: "691159fee7df4e04a0ec3754d5cf42aa" member_type: VOTER }
I20260812 06:19:34.304327  9707 raft_consensus.cc:399] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:34.304368  9707 raft_consensus.cc:493] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:34.304453  9707 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:34.305261  9707 raft_consensus.cc:515] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "691159fee7df4e04a0ec3754d5cf42aa" member_type: VOTER }
I20260812 06:19:34.305655  9707 leader_election.cc:304] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [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: 691159fee7df4e04a0ec3754d5cf42aa; no voters: 
I20260812 06:19:34.305934  9707 leader_election.cc:290] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:34.306107  9710 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:34.306391  9710 raft_consensus.cc:697] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 1 LEADER]: Becoming Leader. State: Replica: 691159fee7df4e04a0ec3754d5cf42aa, State: Running, Role: LEADER
I20260812 06:19:34.306878  9710 consensus_queue.cc:237] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [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: "691159fee7df4e04a0ec3754d5cf42aa" member_type: VOTER }
I20260812 06:19:34.306969  9707 sys_catalog.cc:565] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:34.308964  9712 sys_catalog.cc:455] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [sys.catalog]: SysCatalogTable state changed. Reason: New leader 691159fee7df4e04a0ec3754d5cf42aa. Latest consensus state: current_term: 1 leader_uuid: "691159fee7df4e04a0ec3754d5cf42aa" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "691159fee7df4e04a0ec3754d5cf42aa" member_type: VOTER } }
I20260812 06:19:34.308941  9711 sys_catalog.cc:455] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "691159fee7df4e04a0ec3754d5cf42aa" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "691159fee7df4e04a0ec3754d5cf42aa" member_type: VOTER } }
I20260812 06:19:34.309131  9712 sys_catalog.cc:458] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:34.309135  9711 sys_catalog.cc:458] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:34.309563  9721 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:34.312001  9721 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:34.312290  9632 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:34.316756  9721 catalog_manager.cc:1383] Generated new cluster ID: e9320b02d896454c95a0bca48335a672
I20260812 06:19:34.316829  9721 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:34.326608  9721 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:34.327582  9721 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:34.333868  9721 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa: Generated new TSK 0
I20260812 06:19:34.334513  9721 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:34.345198  9632 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:34.348292  9734 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:34.348397  9738 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:34.348311  9736 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:34.348634  9632 server_base.cc:1061] running on GCE node
I20260812 06:19:34.348796  9632 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:34.348842  9632 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:34.348865  9632 hybrid_clock.cc:648] HybridClock initialized: now 1786515574348864 us; error 0 us; skew 500 ppm
I20260812 06:19:34.349857  9632 webserver.cc:533] Webserver started at http://127.9.104.1:39145/ using document root <none> and password file <none>
I20260812 06:19:34.350030  9632 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:34.350086  9632 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:34.350162  9632 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:34.350610  9632 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/instance:
uuid: "7ff51271aabc46148c383267d23d5a0a"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-wl2h"
I20260812 06:19:34.352535  9632 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:34.353716  9744 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:34.354092  9632 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:34.354206  9632 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root
uuid: "7ff51271aabc46148c383267d23d5a0a"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-wl2h"
I20260812 06:19:34.354313  9632 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:34.371505  9632 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:34.372004  9632 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:34.372524  9632 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:34.373600  9632 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:34.373677  9632 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:34.373751  9632 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:34.373783  9632 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:34.380746  9632 rpc_server.cc:307] RPC server started. Bound to: 127.9.104.1:38275
I20260812 06:19:34.380789  9825 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.104.1:38275 every 8 connection(s)
I20260812 06:19:34.396338  9826 heartbeater.cc:344] Connected to a master server at 127.9.104.62:36591
I20260812 06:19:34.396611  9826 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:34.397118  9826 heartbeater.cc:507] Master 127.9.104.62:36591 requested a full tablet report, sending...
I20260812 06:19:34.398684  9664 ts_manager.cc:194] Registered new tserver with Master: 7ff51271aabc46148c383267d23d5a0a (127.9.104.1:38275)
I20260812 06:19:34.399241  9632 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0177964s
I20260812 06:19:34.400439  9664 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46378
I20260812 06:19:34.410023  9664 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46380:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:34.423761  9780 tablet_service.cc:1511] Processing CreateTablet for tablet 5756d8d7b0724306997c5f447daf68f6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=28aa339f80b6458493523b530855481f]), partition=
I20260812 06:19:34.424271  9780 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5756d8d7b0724306997c5f447daf68f6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:34.426690  9842 tablet_bootstrap.cc:492] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Bootstrap starting.
I20260812 06:19:34.427870  9842 tablet_bootstrap.cc:654] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:34.429052  9842 tablet_bootstrap.cc:492] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: No bootstrap required, opened a new log
I20260812 06:19:34.429177  9842 ts_tablet_manager.cc:1403] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:34.429631  9842 raft_consensus.cc:359] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7ff51271aabc46148c383267d23d5a0a" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 38275 } }
I20260812 06:19:34.429767  9842 raft_consensus.cc:385] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:34.429817  9842 raft_consensus.cc:740] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7ff51271aabc46148c383267d23d5a0a, State: Initialized, Role: FOLLOWER
I20260812 06:19:34.429958  9842 consensus_queue.cc:260] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [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: "7ff51271aabc46148c383267d23d5a0a" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 38275 } }
I20260812 06:19:34.430054  9842 raft_consensus.cc:399] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:34.430102  9842 raft_consensus.cc:493] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:34.430157  9842 raft_consensus.cc:3060] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:34.431427  9842 raft_consensus.cc:515] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7ff51271aabc46148c383267d23d5a0a" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 38275 } }
I20260812 06:19:34.431608  9842 leader_election.cc:304] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [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: 7ff51271aabc46148c383267d23d5a0a; no voters: 
I20260812 06:19:34.431881  9842 leader_election.cc:290] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:34.432121  9844 raft_consensus.cc:2804] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:34.432253  9842 ts_tablet_manager.cc:1434] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:34.432356  9844 raft_consensus.cc:697] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 1 LEADER]: Becoming Leader. State: Replica: 7ff51271aabc46148c383267d23d5a0a, State: Running, Role: LEADER
I20260812 06:19:34.432472  9826 heartbeater.cc:499] Master 127.9.104.62:36591 was elected leader, sending a full tablet report...
I20260812 06:19:34.432528  9844 consensus_queue.cc:237] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [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: "7ff51271aabc46148c383267d23d5a0a" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 38275 } }
I20260812 06:19:34.435081  9664 catalog_manager.cc:5719] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a reported cstate change: term changed from 0 to 1, leader changed from <none> to 7ff51271aabc46148c383267d23d5a0a (127.9.104.1). New cstate: current_term: 1 leader_uuid: "7ff51271aabc46148c383267d23d5a0a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7ff51271aabc46148c383267d23d5a0a" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 38275 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:34.501983  9632 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.021s	sys 0.008s
I20260812 06:19:34.632077  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushMRSOp(5756d8d7b0724306997c5f447daf68f6): perf score=15.086190
I20260812 06:19:34.765952  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushMRSOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.133s	user 0.094s	sys 0.035s Metrics: {"bytes_written":9025561,"cfile_init":1,"compiler_manager_pool.queue_time_us":4328,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":804,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":31048,"lbm_writes_lt_1ms":587,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":170624,"thread_start_us":126,"threads_started":1,"update_count":1100}
I20260812 06:19:34.767140  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling LogGCOp(5756d8d7b0724306997c5f447daf68f6): free 20743880 bytes of WAL
I20260812 06:19:34.767443  9750 log_reader.cc:385] T 5756d8d7b0724306997c5f447daf68f6: removed 2 log segments from log reader
I20260812 06:19:34.767521  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000001 (ops 1-6)
I20260812 06:19:34.767630  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000002 (ops 7-11)
I20260812 06:19:34.772329  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: LogGCOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:34.772928  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling UndoDeltaBlockGCOp(5756d8d7b0724306997c5f447daf68f6): 12719216 bytes on disk
I20260812 06:19:34.773880  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: UndoDeltaBlockGCOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":136,"lbm_reads_lt_1ms":4}
I20260812 06:19:34.774492  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.196750
I20260812 06:19:34.789356  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4690,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:19:34.789923  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:34.898869  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.109s	user 0.076s	sys 0.032s Metrics: {"cfile_cache_miss":322,"cfile_cache_miss_bytes":16159594,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":427,"lbm_read_time_us":7535,"lbm_reads_lt_1ms":350,"lbm_write_time_us":19176,"lbm_writes_lt_1ms":333,"peak_mem_usage":36812022,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":317,"threads_started":5,"update_count":1450}
I20260812 06:19:34.899425  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=7.149875
I20260812 06:19:34.928428  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.029s	user 0.016s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12185,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:34.928875  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:34.940966  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4173,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:34.941781  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:35.059476  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.117s	user 0.083s	sys 0.023s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1092,"lbm_read_time_us":7640,"lbm_reads_lt_1ms":372,"lbm_write_time_us":19427,"lbm_writes_lt_1ms":343,"mutex_wait_us":291,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":1500}
I20260812 06:19:35.060022  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=10.126437
I20260812 06:19:35.109629  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.049s	user 0.034s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18584,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.110138  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:35.120718  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.121176  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:35.243435  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.122s	user 0.099s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":323,"lbm_read_time_us":8669,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21770,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:19:35.243901  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=10.126437
I20260812 06:19:35.289551  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.045s	user 0.024s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15773,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.290088  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:35.300676  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3998,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.301308  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:35.431910  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.130s	user 0.104s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":9323,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25055,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:19:35.432498  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=10.126437
I20260812 06:19:35.481276  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.049s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307522,"delete_count":0,"lbm_write_time_us":15986,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.481729  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:35.492192  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.492659  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:35.617255  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.124s	user 0.092s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672309,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":977,"lbm_read_time_us":8127,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24263,"lbm_writes_lt_1ms":443,"mutex_wait_us":319,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:35.620455  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=10.126437
I20260812 06:19:35.665123  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.044s	user 0.013s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15718,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.665719  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:35.676724  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.677140  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:35.822777  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.145s	user 0.111s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":173,"lbm_read_time_us":10620,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24281,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:35.823418  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=10.126437
I20260812 06:19:35.873034  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.049s	user 0.010s	sys 0.028s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14716,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.873589  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:35.890275  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.891064  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:36.016119  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.125s	user 0.092s	sys 0.032s 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":685,"lbm_read_time_us":10064,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22883,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:19:36.016629  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=10.126437
I20260812 06:19:36.056411  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.040s	user 0.010s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15856,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:36.056903  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:36.068324  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.069041  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushMRSOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:36.101852  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushMRSOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.033s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1222,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1640,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:36.102738  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling LogGCOp(5756d8d7b0724306997c5f447daf68f6): free 112239266 bytes of WAL
I20260812 06:19:36.102964  9750 log_reader.cc:385] T 5756d8d7b0724306997c5f447daf68f6: removed 11 log segments from log reader
I20260812 06:19:36.103006  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000003 (ops 12-16)
I20260812 06:19:36.103107  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000004 (ops 17-21)
I20260812 06:19:36.103148  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000005 (ops 22-26)
I20260812 06:19:36.103185  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000006 (ops 27-31)
I20260812 06:19:36.103221  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000007 (ops 32-36)
I20260812 06:19:36.103258  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000008 (ops 37-41)
I20260812 06:19:36.103295  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000009 (ops 42-46)
I20260812 06:19:36.103333  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000010 (ops 47-50)
I20260812 06:19:36.103369  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000011 (ops 51-55)
I20260812 06:19:36.103404  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000012 (ops 56-60)
I20260812 06:19:36.103440  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000013 (ops 61-65)
I20260812 06:19:36.127601  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: LogGCOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:36.128006  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=3.181125
I20260812 06:19:36.139649  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.011s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4543,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:36.140079  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling LogGCOp(5756d8d7b0724306997c5f447daf68f6): free 12017983 bytes of WAL
I20260812 06:19:36.140288  9750 log_reader.cc:385] T 5756d8d7b0724306997c5f447daf68f6: removed 1 log segments from log reader
I20260812 06:19:36.140329  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000014 (ops 66-70)
I20260812 06:19:36.142577  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: LogGCOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:36.142884  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:36.155911  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:36.156318  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling UndoDeltaBlockGCOp(5756d8d7b0724306997c5f447daf68f6): 462 bytes on disk
I20260812 06:19:36.156924  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: UndoDeltaBlockGCOp(5756d8d7b0724306997c5f447daf68f6) 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:19:36.157347  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:36.333045  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.176s	user 0.131s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":619,"lbm_read_time_us":13735,"lbm_reads_lt_1ms":666,"lbm_write_time_us":33744,"lbm_writes_lt_1ms":643,"mutex_wait_us":123,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:19:36.335197  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=14.095187
I20260812 06:19:36.391911  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.056s	user 0.027s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24610,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.392544  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:36.421665  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.029s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6106,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.422118  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:36.432535  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.432997  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:36.611997  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.179s	user 0.134s	sys 0.042s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877216,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":354,"lbm_read_time_us":11965,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32602,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:36.612529  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=14.095187
I20260812 06:19:36.663231  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.051s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19998,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.663776  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:36.676491  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4832,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.677026  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:36.834987  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.158s	user 0.124s	sys 0.025s 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":276,"lbm_read_time_us":9421,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28718,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:36.835780  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=14.095187
I20260812 06:19:36.897188  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.060s	user 0.040s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23454,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.897959  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:36.913467  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.914203  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:37.067982  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.154s	user 0.122s	sys 0.031s 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":110,"lbm_read_time_us":12489,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30640,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:19:37.068555  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=10.126437
I20260812 06:19:37.102027  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.033s	user 0.030s	sys 0.000s Metrics: {"bytes_written":12430562,"delete_count":0,"lbm_write_time_us":14227,"lbm_writes_lt_1ms":306,"reinsert_count":0,"update_count":1515}
I20260812 06:19:37.102679  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:37.122571  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.020s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3979583,"delete_count":0,"lbm_write_time_us":6215,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:37.123188  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:37.255625  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.132s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":71,"lbm_read_time_us":9082,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24413,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.256294  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=10.126437
I20260812 06:19:37.292272  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.036s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15150,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.293223  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:37.310813  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.311331  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:37.437098  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.126s	user 0.105s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1025,"lbm_read_time_us":9154,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23356,"lbm_writes_lt_1ms":443,"mutex_wait_us":271,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:19:37.437920  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=10.126437
I20260812 06:19:37.488051  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.050s	user 0.016s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17181,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.488621  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:37.499595  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.500041  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushMRSOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:37.541709  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushMRSOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.041s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":171,"dirs.run_wall_time_us":1200,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1417,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:37.542611  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling LogGCOp(5756d8d7b0724306997c5f447daf68f6): free 117302581 bytes of WAL
I20260812 06:19:37.542876  9750 log_reader.cc:385] T 5756d8d7b0724306997c5f447daf68f6: removed 12 log segments from log reader
I20260812 06:19:37.542943  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000015 (ops 71-75)
I20260812 06:19:37.542992  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000016 (ops 76-80)
I20260812 06:19:37.543079  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000017 (ops 81-84)
I20260812 06:19:37.543111  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000018 (ops 85-89)
I20260812 06:19:37.543210  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000019 (ops 90-94)
I20260812 06:19:37.543262  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000020 (ops 95-99)
I20260812 06:19:37.543303  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000021 (ops 100-104)
I20260812 06:19:37.543341  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000022 (ops 105-108)
I20260812 06:19:37.543381  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000023 (ops 109-113)
I20260812 06:19:37.543423  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000024 (ops 114-118)
I20260812 06:19:37.543463  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000025 (ops 119-123)
I20260812 06:19:37.543502  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000026 (ops 124-128)
I20260812 06:19:37.567902  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: LogGCOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:37.568356  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:37.586673  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.018s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.587198  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:37.597803  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3996,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.598450  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:37.799182  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.201s	user 0.140s	sys 0.060s 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":1130,"lbm_read_time_us":14821,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34106,"lbm_writes_lt_1ms":643,"mutex_wait_us":338,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19072,"thread_start_us":112,"threads_started":1,"update_count":3000}
I20260812 06:19:37.799880  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=14.095187
I20260812 06:19:37.867551  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.067s	user 0.039s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24532,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.868038  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling UndoDeltaBlockGCOp(5756d8d7b0724306997c5f447daf68f6): 473 bytes on disk
I20260812 06:19:37.868462  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: UndoDeltaBlockGCOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:37.868971  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:37.880846  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.881457  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:38.055184  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.174s	user 0.109s	sys 0.060s 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":1003,"lbm_read_time_us":12705,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29249,"lbm_writes_lt_1ms":543,"mutex_wait_us":12,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":47232,"update_count":2500}
I20260812 06:19:38.055868  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=14.095187
I20260812 06:19:38.123266  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.067s	user 0.025s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22393,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.123847  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:38.134735  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.135255  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:38.311645  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.176s	user 0.121s	sys 0.052s 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":217,"lbm_read_time_us":12580,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30260,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:38.312443  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=11.118625
I20260812 06:19:38.346516  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.034s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14041,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:38.347198  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:38.363497  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5828,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.363947  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:38.511821  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.148s	user 0.100s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":791,"lbm_read_time_us":9029,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22808,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:19:38.512413  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=11.118625
I20260812 06:19:38.554337  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.042s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":20447,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:38.554840  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:38.576228  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.021s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5150,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.576877  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:38.587735  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4001,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.588275  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:38.753576  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.165s	user 0.122s	sys 0.031s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":807,"lbm_read_time_us":10968,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30986,"lbm_writes_lt_1ms":543,"mutex_wait_us":251,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:38.754256  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=14.095187
I20260812 06:19:38.809885  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.055s	user 0.044s	sys 0.004s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21162,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.810391  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:38.821933  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.822654  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:38.971771  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.149s	user 0.101s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":11124,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29422,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:19:38.972432  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=11.118625
I20260812 06:19:39.004606  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13813,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:39.005156  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:39.019877  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5245,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:39.021090  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushMRSOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:39.053689  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushMRSOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1655,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2115,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:39.054405  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling LogGCOp(5756d8d7b0724306997c5f447daf68f6): free 123804445 bytes of WAL
I20260812 06:19:39.054654  9750 log_reader.cc:385] T 5756d8d7b0724306997c5f447daf68f6: removed 12 log segments from log reader
I20260812 06:19:39.054724  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000027 (ops 129-132)
I20260812 06:19:39.054775  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000028 (ops 133-137)
I20260812 06:19:39.054840  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000029 (ops 138-142)
I20260812 06:19:39.054890  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000030 (ops 143-147)
I20260812 06:19:39.054934  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000031 (ops 148-152)
I20260812 06:19:39.054978  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000032 (ops 153-157)
I20260812 06:19:39.055043  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000033 (ops 158-162)
I20260812 06:19:39.055084  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000034 (ops 163-167)
I20260812 06:19:39.055112  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000035 (ops 168-172)
I20260812 06:19:39.055146  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000036 (ops 173-177)
I20260812 06:19:39.055188  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000037 (ops 178-182)
I20260812 06:19:39.055259  9750 log.cc:1079] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/5756d8d7b0724306997c5f447daf68f6/wal-000000038 (ops 183-186)
I20260812 06:19:39.083847  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: LogGCOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:39.084373  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling UndoDeltaBlockGCOp(5756d8d7b0724306997c5f447daf68f6): 472 bytes on disk
I20260812 06:19:39.085112  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: UndoDeltaBlockGCOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:19:39.085829  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=3.181125
I20260812 06:19:39.097985  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4553929,"delete_count":0,"lbm_write_time_us":4816,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:19:39.098415  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:39.108265  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3725,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:19:39.108691  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:39.277580  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.169s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1890,"lbm_read_time_us":12093,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32537,"lbm_writes_lt_1ms":643,"mutex_wait_us":544,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20480,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:19:39.278242  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=14.095187
I20260812 06:19:39.323511  9632 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.821s	user 1.787s	sys 0.118s
I20260812 06:19:39.326792  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.048s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21012,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.327368  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6): perf score=2.188937
I20260812 06:19:39.337880  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: FlushDeltaMemStoresOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.338330  9827 maintenance_manager.cc:419] P 7ff51271aabc46148c383267d23d5a0a: Scheduling MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6): perf score=1.000000
I20260812 06:19:39.373734  9632 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.050s	user 0.003s	sys 0.000s
I20260812 06:19:39.374571  9632 tablet_server.cc:179] TabletServer@127.9.104.1:0 shutting down...
I20260812 06:19:39.456619  9750 maintenance_manager.cc:643] P 7ff51271aabc46148c383267d23d5a0a: MajorDeltaCompactionOp(5756d8d7b0724306997c5f447daf68f6) complete. Timing: real 0.118s	user 0.115s	sys 0.002s Metrics: {"cfile_cache_hit":304,"cfile_cache_hit_bytes":12431700,"cfile_cache_miss":228,"cfile_cache_miss_bytes":12342988,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1129,"lbm_read_time_us":4818,"lbm_reads_lt_1ms":260,"lbm_write_time_us":26773,"lbm_writes_lt_1ms":543,"mutex_wait_us":325,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":70272,"update_count":2500}
I20260812 06:19:39.457405  9632 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:39.457851  9632 tablet_replica.cc:333] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a: stopping tablet replica
I20260812 06:19:39.458099  9632 raft_consensus.cc:2243] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:39.458348  9632 raft_consensus.cc:2272] T 5756d8d7b0724306997c5f447daf68f6 P 7ff51271aabc46148c383267d23d5a0a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:39.463960  9632 tablet_server.cc:196] TabletServer@127.9.104.1:0 shutdown complete.
I20260812 06:19:39.502074  9632 master.cc:562] Master@127.9.104.62:36591 shutting down...
I20260812 06:19:39.506108  9632 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:39.506292  9632 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:39.506346  9632 tablet_replica.cc:333] T 00000000000000000000000000000000 P 691159fee7df4e04a0ec3754d5cf42aa: stopping tablet replica
I20260812 06:19:39.518814  9632 master.cc:584] Master@127.9.104.62:36591 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5363 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:39.617741  9632 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.104.62:38123
I20260812 06:19:39.618146  9632 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:39.620258  9862 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:39.620283  9632 server_base.cc:1061] running on GCE node
W20260812 06:19:39.620468  9865 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:39.620469  9863 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:39.620785  9632 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:39.620852  9632 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:39.620879  9632 hybrid_clock.cc:648] HybridClock initialized: now 1786515579620878 us; error 0 us; skew 500 ppm
I20260812 06:19:39.621768  9632 webserver.cc:533] Webserver started at http://127.9.104.62:40657/ using document root <none> and password file <none>
I20260812 06:19:39.621941  9632 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:39.622009  9632 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:39.622090  9632 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:39.622486  9632 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/master-0-root/instance:
uuid: "e28c3e79a34a4b87883943fd630799a1"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-wl2h"
I20260812 06:19:39.624191  9632 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:39.625329  9872 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.625664  9632 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:39.625773  9632 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/master-0-root
uuid: "e28c3e79a34a4b87883943fd630799a1"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-wl2h"
I20260812 06:19:39.625869  9632 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:39.650727  9632 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:39.651264  9632 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:39.656251  9632 rpc_server.cc:307] RPC server started. Bound to: 127.9.104.62:38123
I20260812 06:19:39.657544  9936 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.104.62:38123 every 8 connection(s)
I20260812 06:19:39.658625  9937 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:39.663210  9937 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1: Bootstrap starting.
I20260812 06:19:39.663971  9937 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:39.665020  9937 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1: No bootstrap required, opened a new log
I20260812 06:19:39.665419  9937 raft_consensus.cc:359] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e28c3e79a34a4b87883943fd630799a1" member_type: VOTER }
I20260812 06:19:39.665504  9937 raft_consensus.cc:385] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:39.665526  9937 raft_consensus.cc:740] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e28c3e79a34a4b87883943fd630799a1, State: Initialized, Role: FOLLOWER
I20260812 06:19:39.665628  9937 consensus_queue.cc:260] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [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: "e28c3e79a34a4b87883943fd630799a1" member_type: VOTER }
I20260812 06:19:39.665688  9937 raft_consensus.cc:399] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:39.665709  9937 raft_consensus.cc:493] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:39.665737  9937 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:39.666386  9937 raft_consensus.cc:515] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e28c3e79a34a4b87883943fd630799a1" member_type: VOTER }
I20260812 06:19:39.666495  9937 leader_election.cc:304] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [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: e28c3e79a34a4b87883943fd630799a1; no voters: 
I20260812 06:19:39.666643  9937 leader_election.cc:290] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:39.666801  9941 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:39.667069  9941 raft_consensus.cc:697] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 1 LEADER]: Becoming Leader. State: Replica: e28c3e79a34a4b87883943fd630799a1, State: Running, Role: LEADER
I20260812 06:19:39.667172  9937 sys_catalog.cc:565] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:39.667261  9941 consensus_queue.cc:237] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [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: "e28c3e79a34a4b87883943fd630799a1" member_type: VOTER }
I20260812 06:19:39.667755  9945 sys_catalog.cc:455] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e28c3e79a34a4b87883943fd630799a1. Latest consensus state: current_term: 1 leader_uuid: "e28c3e79a34a4b87883943fd630799a1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e28c3e79a34a4b87883943fd630799a1" member_type: VOTER } }
I20260812 06:19:39.667742  9942 sys_catalog.cc:455] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e28c3e79a34a4b87883943fd630799a1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e28c3e79a34a4b87883943fd630799a1" member_type: VOTER } }
I20260812 06:19:39.667865  9945 sys_catalog.cc:458] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.667876  9942 sys_catalog.cc:458] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.668551  9950 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:39.669490  9950 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:39.669715  9632 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:39.671458  9950 catalog_manager.cc:1383] Generated new cluster ID: 8e0bfe0851c94f7aae73334f319cb9b0
I20260812 06:19:39.671509  9950 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:39.684254  9950 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:39.684808  9950 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:39.690158  9950 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1: Generated new TSK 0
I20260812 06:19:39.690402  9950 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:39.702512  9632 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:39.704931  9965 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:39.704936  9966 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:39.705264  9970 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:39.705231  9632 server_base.cc:1061] running on GCE node
I20260812 06:19:39.705519  9632 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:39.705572  9632 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:39.705600  9632 hybrid_clock.cc:648] HybridClock initialized: now 1786515579705598 us; error 0 us; skew 500 ppm
I20260812 06:19:39.706784  9632 webserver.cc:533] Webserver started at http://127.9.104.1:38713/ using document root <none> and password file <none>
I20260812 06:19:39.706980  9632 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:39.707067  9632 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:39.707152  9632 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:39.707647  9632 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/instance:
uuid: "732815114c51464f8fbfc8900aa2c164"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-wl2h"
I20260812 06:19:39.710646  9632 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:19:39.711984  9976 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.712699  9632 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:39.712795  9632 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root
uuid: "732815114c51464f8fbfc8900aa2c164"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-wl2h"
I20260812 06:19:39.712855  9632 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:39.725497  9632 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:39.725829  9632 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:39.726094  9632 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:39.726562  9632 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:39.726599  9632 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.726661  9632 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:39.726701  9632 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.731192  9632 rpc_server.cc:307] RPC server started. Bound to: 127.9.104.1:42921
I20260812 06:19:39.731768 10057 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.104.1:42921 every 8 connection(s)
I20260812 06:19:39.741153 10058 heartbeater.cc:344] Connected to a master server at 127.9.104.62:38123
I20260812 06:19:39.741286 10058 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:39.741504 10058 heartbeater.cc:507] Master 127.9.104.62:38123 requested a full tablet report, sending...
I20260812 06:19:39.742211  9891 ts_manager.cc:194] Registered new tserver with Master: 732815114c51464f8fbfc8900aa2c164 (127.9.104.1:42921)
I20260812 06:19:39.742945  9891 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33164
I20260812 06:19:39.743083  9632 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011200946s
I20260812 06:19:39.750344  9891 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33178:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:39.759181 10017 tablet_service.cc:1511] Processing CreateTablet for tablet 697723c6423a4247b3c18b28a1e542f4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=76096c5b7a744d479c60a6a05a4ac2c5]), partition=
I20260812 06:19:39.759428 10017 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 697723c6423a4247b3c18b28a1e542f4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:39.761276 10073 tablet_bootstrap.cc:492] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Bootstrap starting.
I20260812 06:19:39.762122 10073 tablet_bootstrap.cc:654] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:39.763247 10073 tablet_bootstrap.cc:492] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: No bootstrap required, opened a new log
I20260812 06:19:39.763343 10073 ts_tablet_manager.cc:1403] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:39.763810 10073 raft_consensus.cc:359] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "732815114c51464f8fbfc8900aa2c164" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 42921 } }
I20260812 06:19:39.763899 10073 raft_consensus.cc:385] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:39.763921 10073 raft_consensus.cc:740] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 732815114c51464f8fbfc8900aa2c164, State: Initialized, Role: FOLLOWER
I20260812 06:19:39.764098 10073 consensus_queue.cc:260] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [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: "732815114c51464f8fbfc8900aa2c164" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 42921 } }
I20260812 06:19:39.764187 10073 raft_consensus.cc:399] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:39.764211 10073 raft_consensus.cc:493] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:39.764264 10073 raft_consensus.cc:3060] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:39.765095 10073 raft_consensus.cc:515] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "732815114c51464f8fbfc8900aa2c164" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 42921 } }
I20260812 06:19:39.765239 10073 leader_election.cc:304] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [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: 732815114c51464f8fbfc8900aa2c164; no voters: 
I20260812 06:19:39.765395 10073 leader_election.cc:290] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:39.765537 10076 raft_consensus.cc:2804] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:39.765758 10073 ts_tablet_manager.cc:1434] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:39.765769 10058 heartbeater.cc:499] Master 127.9.104.62:38123 was elected leader, sending a full tablet report...
I20260812 06:19:39.765841 10076 raft_consensus.cc:697] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 1 LEADER]: Becoming Leader. State: Replica: 732815114c51464f8fbfc8900aa2c164, State: Running, Role: LEADER
I20260812 06:19:39.765959 10076 consensus_queue.cc:237] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [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: "732815114c51464f8fbfc8900aa2c164" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 42921 } }
I20260812 06:19:39.767310  9891 catalog_manager.cc:5719] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 reported cstate change: term changed from 0 to 1, leader changed from <none> to 732815114c51464f8fbfc8900aa2c164 (127.9.104.1). New cstate: current_term: 1 leader_uuid: "732815114c51464f8fbfc8900aa2c164" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "732815114c51464f8fbfc8900aa2c164" member_type: VOTER last_known_addr { host: "127.9.104.1" port: 42921 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:39.834405  9632 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.018s	sys 0.008s
I20260812 06:19:39.982486 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushMRSOp(697723c6423a4247b3c18b28a1e542f4): perf score=19.054940
I20260812 06:19:40.145661  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushMRSOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.163s	user 0.109s	sys 0.051s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":183,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":849,"drs_written":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38317,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:40.146394 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling LogGCOp(697723c6423a4247b3c18b28a1e542f4): free 20743880 bytes of WAL
I20260812 06:19:40.146647  9985 log_reader.cc:385] T 697723c6423a4247b3c18b28a1e542f4: removed 2 log segments from log reader
I20260812 06:19:40.146718  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000001 (ops 1-6)
I20260812 06:19:40.146852  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000002 (ops 7-11)
I20260812 06:19:40.152345  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: LogGCOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:40.152640 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling UndoDeltaBlockGCOp(697723c6423a4247b3c18b28a1e542f4): 16411396 bytes on disk
I20260812 06:19:40.153023  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: UndoDeltaBlockGCOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.153410 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=3.181125
I20260812 06:19:40.175666  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.022s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:40.176160 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:40.185804  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.186358 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:40.375877  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.189s	user 0.139s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774794,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":644,"lbm_read_time_us":12442,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30861,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":341,"threads_started":5,"update_count":2500}
I20260812 06:19:40.376667 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=14.095187
I20260812 06:19:40.420323  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.043s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19312,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.420892 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:40.563372  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.142s	user 0.091s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":52,"lbm_read_time_us":10563,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23251,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":80384,"update_count":2000}
I20260812 06:19:40.564113 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=11.118625
I20260812 06:19:40.597884  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.034s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13566,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:40.598402 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:40.624404  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5299,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.625018 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:40.641083  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.641690 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:40.855193  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.213s	user 0.123s	sys 0.076s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":875,"lbm_read_time_us":13507,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32469,"lbm_writes_lt_1ms":543,"mutex_wait_us":203,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:19:40.855919 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=14.095187
I20260812 06:19:40.905596  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.050s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21408,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.906026 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:40.917738  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.918231 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:41.077597  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.159s	user 0.103s	sys 0.055s 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":328,"lbm_read_time_us":12227,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30396,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":2500}
I20260812 06:19:41.078135 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=10.126437
I20260812 06:19:41.109921  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.032s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13863,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.110484 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:41.124107  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.124655 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:41.257195  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.132s	user 0.106s	sys 0.026s 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":751,"lbm_read_time_us":8812,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26820,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26624,"update_count":2000}
I20260812 06:19:41.257799 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=10.126437
I20260812 06:19:41.306528  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.049s	user 0.033s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19581,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.307121 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:41.325130  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.018s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7883,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.325676 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:41.461737  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.136s	user 0.109s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":149,"lbm_read_time_us":10270,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28434,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:41.462419 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=6.157687
I20260812 06:19:41.504964  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.042s	user 0.015s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10418,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:41.505460 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:41.532449  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.027s	user 0.008s	sys 0.018s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.533242 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushMRSOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:41.593139  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushMRSOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.060s	user 0.028s	sys 0.009s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1364,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1845,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:41.593927 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling LogGCOp(697723c6423a4247b3c18b28a1e542f4): free 121006433 bytes of WAL
I20260812 06:19:41.594225  9985 log_reader.cc:385] T 697723c6423a4247b3c18b28a1e542f4: removed 12 log segments from log reader
I20260812 06:19:41.594298  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000003 (ops 12-16)
I20260812 06:19:41.594391  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000004 (ops 17-21)
I20260812 06:19:41.594455  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000005 (ops 22-26)
I20260812 06:19:41.594525  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000006 (ops 27-31)
I20260812 06:19:41.594586  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000007 (ops 32-36)
I20260812 06:19:41.594660  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000008 (ops 37-41)
I20260812 06:19:41.594702  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000009 (ops 42-46)
I20260812 06:19:41.594748  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000010 (ops 47-50)
I20260812 06:19:41.594810  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000011 (ops 51-55)
I20260812 06:19:41.594848  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000012 (ops 56-60)
I20260812 06:19:41.594892  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000013 (ops 61-65)
I20260812 06:19:41.594933  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000014 (ops 66-70)
I20260812 06:19:41.619995  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: LogGCOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:41.620584 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:41.651503  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.031s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.652204 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling UndoDeltaBlockGCOp(697723c6423a4247b3c18b28a1e542f4): 472 bytes on disk
I20260812 06:19:41.652750  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: UndoDeltaBlockGCOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":114,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.653393 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:41.672595  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.673237 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:41.882653  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.209s	user 0.117s	sys 0.080s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24774927,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":469,"lbm_read_time_us":18474,"lbm_reads_lt_1ms":574,"lbm_write_time_us":31135,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":78,"threads_started":1,"update_count":2500}
I20260812 06:19:41.883424 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=18.063937
I20260812 06:19:41.948137  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.064s	user 0.051s	sys 0.012s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28397,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:41.948714 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:41.962287  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.962872 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:42.168836  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.206s	user 0.133s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":15807,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35818,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":3000}
I20260812 06:19:42.170197 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=14.095187
I20260812 06:19:42.221310  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22270,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.221954 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:42.248059  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.026s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.248543 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:42.263386  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5712,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.263923 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:42.475589  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.211s	user 0.118s	sys 0.088s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":320,"lbm_read_time_us":14857,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33260,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":3000}
I20260812 06:19:42.476346 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=16.079562
I20260812 06:19:42.552515  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.076s	user 0.035s	sys 0.024s Metrics: {"bytes_written":17558579,"delete_count":0,"lbm_write_time_us":30756,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":429,"reinsert_count":0,"update_count":2140}
I20260812 06:19:42.552968 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=5.165500
I20260812 06:19:42.575897  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.023s	user 0.011s	sys 0.008s Metrics: {"bytes_written":7056406,"delete_count":0,"lbm_write_time_us":7996,"lbm_writes_lt_1ms":175,"reinsert_count":0,"update_count":860}
I20260812 06:19:42.576524 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:42.765664  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.189s	user 0.135s	sys 0.051s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":344,"lbm_read_time_us":12312,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32165,"lbm_writes_lt_1ms":643,"mutex_wait_us":17,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3000}
I20260812 06:19:42.767028 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=17.071750
I20260812 06:19:42.836302  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.069s	user 0.041s	sys 0.016s Metrics: {"bytes_written":18748280,"delete_count":0,"lbm_write_time_us":26280,"lbm_writes_lt_1ms":460,"reinsert_count":0,"update_count":2285}
I20260812 06:19:42.836791 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=4.173312
I20260812 06:19:42.852466  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":5866708,"delete_count":0,"lbm_write_time_us":6368,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:19:42.853091 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:43.076133  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.223s	user 0.138s	sys 0.074s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877110,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":860,"lbm_read_time_us":15963,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34998,"lbm_writes_lt_1ms":643,"mutex_wait_us":355,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":3000}
I20260812 06:19:43.076828 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=18.063937
I20260812 06:19:43.150704  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.074s	user 0.036s	sys 0.024s Metrics: {"bytes_written":20512311,"delete_count":0,"lbm_write_time_us":28675,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:43.151300 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:43.162696  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4064,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.163254 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushMRSOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:43.199214  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushMRSOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.036s	user 0.035s	sys 0.001s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1288,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1719,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:43.200119 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling LogGCOp(697723c6423a4247b3c18b28a1e542f4): free 136728271 bytes of WAL
I20260812 06:19:43.200424  9985 log_reader.cc:385] T 697723c6423a4247b3c18b28a1e542f4: removed 13 log segments from log reader
I20260812 06:19:43.200498  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000015 (ops 71-75)
I20260812 06:19:43.200562  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000016 (ops 76-80)
I20260812 06:19:43.200627  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000017 (ops 81-85)
I20260812 06:19:43.200671  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000018 (ops 86-90)
I20260812 06:19:43.200708  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000019 (ops 91-95)
I20260812 06:19:43.200744  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000020 (ops 96-100)
I20260812 06:19:43.200783  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000021 (ops 101-105)
I20260812 06:19:43.200822  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000022 (ops 106-110)
I20260812 06:19:43.200858  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000023 (ops 111-115)
I20260812 06:19:43.200896  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000024 (ops 116-120)
I20260812 06:19:43.200933  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000025 (ops 121-125)
I20260812 06:19:43.200970  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000026 (ops 126-130)
I20260812 06:19:43.201007  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000027 (ops 131-135)
I20260812 06:19:43.228471  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: LogGCOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:43.228902 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=5.165500
I20260812 06:19:43.250138  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.021s	user 0.011s	sys 0.007s Metrics: {"bytes_written":6851279,"delete_count":0,"lbm_write_time_us":8854,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:19:43.250705 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling UndoDeltaBlockGCOp(697723c6423a4247b3c18b28a1e542f4): 493 bytes on disk
I20260812 06:19:43.251718  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: UndoDeltaBlockGCOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.252317 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:43.259588  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.007s	user 0.005s	sys 0.002s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":1883,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:19:43.260131 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:43.502491  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.242s	user 0.156s	sys 0.085s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082093,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":452,"lbm_read_time_us":19301,"lbm_reads_lt_1ms":866,"lbm_write_time_us":43545,"lbm_writes_lt_1ms":843,"mutex_wait_us":30,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":14592,"thread_start_us":83,"threads_started":1,"update_count":4000}
I20260812 06:19:43.503455 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=18.063937
I20260812 06:19:43.575793  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.072s	user 0.044s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31847,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:19:43.576395 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=3.181125
I20260812 06:19:43.589432  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4709,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:43.589917 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:43.601116  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.601814 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:43.786506  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.184s	user 0.147s	sys 0.036s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979620,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":676,"lbm_read_time_us":14684,"lbm_reads_lt_1ms":773,"lbm_write_time_us":36457,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":3500}
I20260812 06:19:43.787237 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=14.095187
I20260812 06:19:43.837972  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.051s	user 0.035s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22550,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.838541 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:43.859743  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.021s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.860208 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:44.024943  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.165s	user 0.113s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":10528,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30655,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:19:44.025477 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=14.095187
I20260812 06:19:44.080700  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.055s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19878,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.081225 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:44.093710  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.094290 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:44.281677  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.187s	user 0.136s	sys 0.051s 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":210,"lbm_read_time_us":12558,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30321,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:19:44.282444 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=14.095187
I20260812 06:19:44.332562  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.050s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20537,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.333056 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:44.478955  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.146s	user 0.094s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":618,"lbm_read_time_us":9288,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25607,"lbm_writes_lt_1ms":443,"mutex_wait_us":293,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:19:44.479669 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=14.095187
I20260812 06:19:44.532662  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.053s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18480,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.533196 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:44.545370  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4196,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.545972 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushMRSOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:44.580981  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushMRSOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.035s	user 0.024s	sys 0.008s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":168,"dirs.run_wall_time_us":1341,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2035,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:44.581717 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling LogGCOp(697723c6423a4247b3c18b28a1e542f4): free 111786505 bytes of WAL
I20260812 06:19:44.581993  9985 log_reader.cc:385] T 697723c6423a4247b3c18b28a1e542f4: removed 11 log segments from log reader
I20260812 06:19:44.582055  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000028 (ops 136-140)
I20260812 06:19:44.582095  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000029 (ops 141-144)
I20260812 06:19:44.582118  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000030 (ops 145-149)
I20260812 06:19:44.582147  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000031 (ops 150-154)
I20260812 06:19:44.582180  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000032 (ops 155-159)
I20260812 06:19:44.582230  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000033 (ops 160-164)
I20260812 06:19:44.582254  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000034 (ops 165-169)
I20260812 06:19:44.582283  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000035 (ops 170-174)
I20260812 06:19:44.582311  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000036 (ops 175-179)
I20260812 06:19:44.582333  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000037 (ops 180-184)
I20260812 06:19:44.582368  9985 log.cc:1079] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: Deleting log segment in path: /tmp/dist-test-tasku5Tqjq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574232273-9632-0/minicluster-data/ts-0-root/wals/697723c6423a4247b3c18b28a1e542f4/wal-000000038 (ops 185-188)
I20260812 06:19:44.611330  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: LogGCOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:44.611826 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling UndoDeltaBlockGCOp(697723c6423a4247b3c18b28a1e542f4): 447 bytes on disk
I20260812 06:19:44.612313  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: UndoDeltaBlockGCOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.612860 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:44.631588  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.019s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4495,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.632054 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=2.188937
I20260812 06:19:44.642710  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.643251 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:44.843963  9632 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.009s	user 1.910s	sys 0.153s
I20260812 06:19:44.882697  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.239s	user 0.159s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14937,"lbm_reads_lt_1ms":770,"lbm_write_time_us":41814,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":3500}
I20260812 06:19:44.883314 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4): perf score=14.095187
I20260812 06:19:44.918579  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: FlushDeltaMemStoresOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.035s	user 0.021s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":16979,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.919145 10059 maintenance_manager.cc:419] P 732815114c51464f8fbfc8900aa2c164: Scheduling MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4): perf score=1.000000
I20260812 06:19:44.956223  9632 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.112s	user 0.002s	sys 0.000s
I20260812 06:19:44.956794  9632 tablet_server.cc:179] TabletServer@127.9.104.1:0 shutting down...
I20260812 06:19:45.055255  9985 maintenance_manager.cc:643] P 732815114c51464f8fbfc8900aa2c164: MajorDeltaCompactionOp(697723c6423a4247b3c18b28a1e542f4) complete. Timing: real 0.136s	user 0.105s	sys 0.027s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1031,"lbm_read_time_us":10921,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27049,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":95,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.056263  9632 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:45.056485  9632 tablet_replica.cc:333] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164: stopping tablet replica
I20260812 06:19:45.056622  9632 raft_consensus.cc:2243] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:45.056803  9632 raft_consensus.cc:2272] T 697723c6423a4247b3c18b28a1e542f4 P 732815114c51464f8fbfc8900aa2c164 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:45.060489  9632 tablet_server.cc:196] TabletServer@127.9.104.1:0 shutdown complete.
I20260812 06:19:45.096961  9632 master.cc:562] Master@127.9.104.62:38123 shutting down...
I20260812 06:19:45.101285  9632 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:45.101464  9632 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:45.101507  9632 tablet_replica.cc:333] T 00000000000000000000000000000000 P e28c3e79a34a4b87883943fd630799a1: stopping tablet replica
I20260812 06:19:45.115290  9632 master.cc:584] Master@127.9.104.62:38123 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5596 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10961 ms total)

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