[==========] 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:17:12.815059 15594 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.58.190:46833
I20260812 06:17:12.816120 15594 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:17:12.816733 15594 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:12.822789 15603 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:17:12.822839 15607 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:17:12.823107 15602 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:17:12.823107 15594 server_base.cc:1061] running on GCE node
I20260812 06:17:12.823686 15594 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:12.823776 15594 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:17:12.823804 15594 hybrid_clock.cc:648] HybridClock initialized: now 1786515432823803 us; error 0 us; skew 500 ppm
I20260812 06:17:12.825546 15594 webserver.cc:533] Webserver started at http://127.15.58.190:42099/ using document root <none> and password file <none>
I20260812 06:17:12.826135 15594 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:12.826198 15594 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:12.826400 15594 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:12.828009 15594 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/master-0-root/instance:
uuid: "c34df88bf5d74ea58cadae4175799392"
format_stamp: "Formatted at 2026-08-12 06:17:12 on dist-test-slave-vpvm"
I20260812 06:17:12.831516 15594 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:12.833637 15615 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:17:12.834771 15594 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:12.834877 15594 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/master-0-root
uuid: "c34df88bf5d74ea58cadae4175799392"
format_stamp: "Formatted at 2026-08-12 06:17:12 on dist-test-slave-vpvm"
I20260812 06:17:12.834985 15594 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-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:17:12.891304 15594 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:12.892032 15594 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:17:12.892197 15594 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:12.899696 15594 rpc_server.cc:307] RPC server started. Bound to: 127.15.58.190:46833
I20260812 06:17:12.899701 15712 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.58.190:46833 every 8 connection(s)
I20260812 06:17:12.902066 15719 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:17:12.907850 15719 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392: Bootstrap starting.
I20260812 06:17:12.910485 15719 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:12.911494 15719 log.cc:826] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:12.913446 15719 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392: No bootstrap required, opened a new log
I20260812 06:17:12.916494 15719 raft_consensus.cc:359] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c34df88bf5d74ea58cadae4175799392" member_type: VOTER }
I20260812 06:17:12.916672 15719 raft_consensus.cc:385] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:12.916735 15719 raft_consensus.cc:740] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c34df88bf5d74ea58cadae4175799392, State: Initialized, Role: FOLLOWER
I20260812 06:17:12.917384 15719 consensus_queue.cc:260] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [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: "c34df88bf5d74ea58cadae4175799392" member_type: VOTER }
I20260812 06:17:12.917539 15719 raft_consensus.cc:399] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:12.917583 15719 raft_consensus.cc:493] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:12.917692 15719 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:12.918603 15719 raft_consensus.cc:515] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c34df88bf5d74ea58cadae4175799392" member_type: VOTER }
I20260812 06:17:12.919088 15719 leader_election.cc:304] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [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: c34df88bf5d74ea58cadae4175799392; no voters: 
I20260812 06:17:12.919445 15719 leader_election.cc:290] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:12.919627 15728 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:12.919845 15728 raft_consensus.cc:697] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 1 LEADER]: Becoming Leader. State: Replica: c34df88bf5d74ea58cadae4175799392, State: Running, Role: LEADER
I20260812 06:17:12.920290 15728 consensus_queue.cc:237] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [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: "c34df88bf5d74ea58cadae4175799392" member_type: VOTER }
I20260812 06:17:12.920578 15719 sys_catalog.cc:565] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:12.922317 15731 sys_catalog.cc:455] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c34df88bf5d74ea58cadae4175799392" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c34df88bf5d74ea58cadae4175799392" member_type: VOTER } }
I20260812 06:17:12.922315 15732 sys_catalog.cc:455] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c34df88bf5d74ea58cadae4175799392. Latest consensus state: current_term: 1 leader_uuid: "c34df88bf5d74ea58cadae4175799392" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c34df88bf5d74ea58cadae4175799392" member_type: VOTER } }
I20260812 06:17:12.922466 15731 sys_catalog.cc:458] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:12.922513 15732 sys_catalog.cc:458] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:12.922858 15594 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:12.922887 15753 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:12.925290 15753 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:12.930070 15753 catalog_manager.cc:1383] Generated new cluster ID: 74e03a1c31794e6c87fee82648cd0624
I20260812 06:17:12.930146 15753 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:12.940351 15753 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:12.941570 15753 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:12.960497 15753 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392: Generated new TSK 0
I20260812 06:17:12.961184 15753 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:12.987869 15594 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:12.991063 15760 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:17:12.991084 15766 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:17:12.991117 15762 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:17:12.991339 15594 server_base.cc:1061] running on GCE node
I20260812 06:17:12.991590 15594 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:12.991648 15594 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:17:12.991670 15594 hybrid_clock.cc:648] HybridClock initialized: now 1786515432991670 us; error 0 us; skew 500 ppm
I20260812 06:17:12.992589 15594 webserver.cc:533] Webserver started at http://127.15.58.129:33371/ using document root <none> and password file <none>
I20260812 06:17:12.992772 15594 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:12.992830 15594 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:12.992902 15594 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:12.993454 15594 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/instance:
uuid: "056c855323454e619eed2360635c0d1c"
format_stamp: "Formatted at 2026-08-12 06:17:12 on dist-test-slave-vpvm"
I20260812 06:17:12.995308 15594 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:12.996446 15776 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:17:12.996809 15594 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:12.996888 15594 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root
uuid: "056c855323454e619eed2360635c0d1c"
format_stamp: "Formatted at 2026-08-12 06:17:12 on dist-test-slave-vpvm"
I20260812 06:17:12.996960 15594 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-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:17:13.005931 15594 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:13.006471 15594 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:13.006919 15594 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:13.007848 15594 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:13.007901 15594 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:13.007951 15594 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:13.007982 15594 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:13.013609 15594 rpc_server.cc:307] RPC server started. Bound to: 127.15.58.129:39331
I20260812 06:17:13.013653 15893 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.58.129:39331 every 8 connection(s)
I20260812 06:17:13.027298 15894 heartbeater.cc:344] Connected to a master server at 127.15.58.190:46833
I20260812 06:17:13.027593 15894 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:13.028079 15894 heartbeater.cc:507] Master 127.15.58.190:46833 requested a full tablet report, sending...
I20260812 06:17:13.029635 15651 ts_manager.cc:194] Registered new tserver with Master: 056c855323454e619eed2360635c0d1c (127.15.58.129:39331)
I20260812 06:17:13.029807 15594 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015546029s
I20260812 06:17:13.031193 15651 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55278
I20260812 06:17:13.040105 15651 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55292:
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:17:13.054010 15829 tablet_service.cc:1511] Processing CreateTablet for tablet d1079cb1b04d4afdae46ff21cdc49cf1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=57030de62d2e4d19bcd21edab44d31f7]), partition=
I20260812 06:17:13.054515 15829 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d1079cb1b04d4afdae46ff21cdc49cf1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:13.057000 15916 tablet_bootstrap.cc:492] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Bootstrap starting.
I20260812 06:17:13.058162 15916 tablet_bootstrap.cc:654] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:13.059224 15916 tablet_bootstrap.cc:492] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: No bootstrap required, opened a new log
I20260812 06:17:13.059324 15916 ts_tablet_manager.cc:1403] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:13.059758 15916 raft_consensus.cc:359] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "056c855323454e619eed2360635c0d1c" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 39331 } }
I20260812 06:17:13.059859 15916 raft_consensus.cc:385] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:13.059891 15916 raft_consensus.cc:740] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 056c855323454e619eed2360635c0d1c, State: Initialized, Role: FOLLOWER
I20260812 06:17:13.060025 15916 consensus_queue.cc:260] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [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: "056c855323454e619eed2360635c0d1c" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 39331 } }
I20260812 06:17:13.060137 15916 raft_consensus.cc:399] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:13.060184 15916 raft_consensus.cc:493] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:13.060231 15916 raft_consensus.cc:3060] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:13.060954 15916 raft_consensus.cc:515] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "056c855323454e619eed2360635c0d1c" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 39331 } }
I20260812 06:17:13.061096 15916 leader_election.cc:304] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [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: 056c855323454e619eed2360635c0d1c; no voters: 
I20260812 06:17:13.061312 15916 leader_election.cc:290] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:13.061435 15921 raft_consensus.cc:2804] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:13.061712 15921 raft_consensus.cc:697] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 1 LEADER]: Becoming Leader. State: Replica: 056c855323454e619eed2360635c0d1c, State: Running, Role: LEADER
I20260812 06:17:13.061933 15921 consensus_queue.cc:237] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [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: "056c855323454e619eed2360635c0d1c" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 39331 } }
I20260812 06:17:13.062203 15894 heartbeater.cc:499] Master 127.15.58.190:46833 was elected leader, sending a full tablet report...
I20260812 06:17:13.061739 15916 ts_tablet_manager.cc:1434] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:13.064613 15651 catalog_manager.cc:5719] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c reported cstate change: term changed from 0 to 1, leader changed from <none> to 056c855323454e619eed2360635c0d1c (127.15.58.129). New cstate: current_term: 1 leader_uuid: "056c855323454e619eed2360635c0d1c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "056c855323454e619eed2360635c0d1c" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 39331 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:13.137706 15594 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.030s	sys 0.003s
I20260812 06:17:13.264811 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushMRSOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=15.086190
I20260812 06:17:13.408299 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushMRSOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.143s	user 0.112s	sys 0.023s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":415,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":850,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33859,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":134,"threads_started":1,"update_count":1450}
I20260812 06:17:13.409246 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling UndoDeltaBlockGCOp(d1079cb1b04d4afdae46ff21cdc49cf1): 12719217 bytes on disk
I20260812 06:17:13.409744 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: UndoDeltaBlockGCOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.410311 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:13.525837 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.115s	user 0.094s	sys 0.016s Metrics: {"cfile_cache_miss":321,"cfile_cache_miss_bytes":16159505,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":945,"lbm_read_time_us":6547,"lbm_reads_lt_1ms":349,"lbm_write_time_us":20935,"lbm_writes_lt_1ms":333,"peak_mem_usage":36812022,"reinsert_count":0,"thread_start_us":430,"threads_started":5,"update_count":1450}
I20260812 06:17:13.526326 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1): free 20743880 bytes of WAL
I20260812 06:17:13.526587 15782 log_reader.cc:385] T d1079cb1b04d4afdae46ff21cdc49cf1: removed 2 log segments from log reader
I20260812 06:17:13.526640 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000001 (ops 1-6)
I20260812 06:17:13.526706 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000002 (ops 7-11)
I20260812 06:17:13.530498 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:13.530825 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:13.574816 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.044s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15194,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.575374 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:13.585585 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3645,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.586233 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:13.705526 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.119s	user 0.092s	sys 0.024s 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":324,"lbm_read_time_us":9452,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20032,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:17:13.706099 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:13.757752 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.052s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17122,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.758302 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:13.768702 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.769158 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:13.914506 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.145s	user 0.102s	sys 0.042s 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":281,"lbm_read_time_us":10579,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22703,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:17:13.915067 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:13.944353 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.029s	user 0.013s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11615,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.944900 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:14.043128 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.098s	user 0.069s	sys 0.027s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":866,"lbm_read_time_us":5805,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19313,"lbm_writes_lt_1ms":343,"mutex_wait_us":60,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":1500}
I20260812 06:17:14.043643 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:14.077643 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.034s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13817,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.078200 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:14.182570 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.104s	user 0.073s	sys 0.029s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569745,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1019,"lbm_read_time_us":7349,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18745,"lbm_writes_lt_1ms":343,"mutex_wait_us":306,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":1500}
I20260812 06:17:14.183095 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:14.214589 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.031s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12995,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":1500}
I20260812 06:17:14.215251 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:14.311103 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.096s	user 0.071s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":233,"lbm_read_time_us":5801,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18220,"lbm_writes_lt_1ms":343,"mutex_wait_us":60,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.311735 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:14.353637 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.042s	user 0.008s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14437,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.354175 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:14.364571 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.365093 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:14.486047 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.121s	user 0.104s	sys 0.015s 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":389,"lbm_read_time_us":9198,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21013,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:17:14.486518 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:14.541327 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.055s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15601,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.541927 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:14.552554 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.553045 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:14.696909 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.144s	user 0.111s	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":605,"lbm_read_time_us":9755,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19919,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:17:14.698180 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:14.741237 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.043s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15355,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.741777 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:14.752029 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.752669 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushMRSOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:14.783547 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushMRSOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1413,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1873,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:14.784350 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1): free 121006435 bytes of WAL
I20260812 06:17:14.784578 15782 log_reader.cc:385] T d1079cb1b04d4afdae46ff21cdc49cf1: removed 12 log segments from log reader
I20260812 06:17:14.784622 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000003 (ops 12-16)
I20260812 06:17:14.784651 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000004 (ops 17-21)
I20260812 06:17:14.784682 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000005 (ops 22-26)
I20260812 06:17:14.784706 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000006 (ops 27-31)
I20260812 06:17:14.784737 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000007 (ops 32-36)
I20260812 06:17:14.784770 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000008 (ops 37-41)
I20260812 06:17:14.784801 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000009 (ops 42-46)
I20260812 06:17:14.784830 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000010 (ops 47-51)
I20260812 06:17:14.784862 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000011 (ops 52-56)
I20260812 06:17:14.784893 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000012 (ops 57-60)
I20260812 06:17:14.784924 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000013 (ops 61-65)
I20260812 06:17:14.784953 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000014 (ops 66-70)
I20260812 06:17:14.808228 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:14.808645 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling UndoDeltaBlockGCOp(d1079cb1b04d4afdae46ff21cdc49cf1): 482 bytes on disk
I20260812 06:17:14.809118 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: UndoDeltaBlockGCOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.809648 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=3.181125
I20260812 06:17:14.826697 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":6767,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:14.827126 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1): free 11564875 bytes of WAL
I20260812 06:17:14.827316 15782 log_reader.cc:385] T d1079cb1b04d4afdae46ff21cdc49cf1: removed 1 log segments from log reader
I20260812 06:17:14.827358 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000015 (ops 71-74)
I20260812 06:17:14.829115 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:14.829428 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:14.845170 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.016s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3354,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.845738 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:15.033627 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.188s	user 0.125s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":438,"lbm_read_time_us":13429,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29875,"lbm_writes_lt_1ms":643,"mutex_wait_us":54,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:17:15.034162 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=14.095187
I20260812 06:17:15.094244 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.060s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19692,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.094901 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:15.105844 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4034,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.106357 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:15.269279 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.163s	user 0.118s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":11759,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26854,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:15.269774 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:15.303418 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.033s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13368,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.303983 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:15.321595 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.322335 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:15.455615 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.133s	user 0.104s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":397,"lbm_read_time_us":9255,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26157,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:15.456265 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:15.502110 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.046s	user 0.018s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21491,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.502652 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:15.514392 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.515026 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:15.627355 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.112s	user 0.090s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":213,"lbm_read_time_us":7687,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20359,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:17:15.628161 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:15.669179 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.041s	user 0.013s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15378,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.669654 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:15.680084 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.680644 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:15.801095 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.120s	user 0.109s	sys 0.007s 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":866,"lbm_read_time_us":8042,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22254,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.801653 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:15.851055 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.049s	user 0.039s	sys 0.006s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16705,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.851635 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:15.862004 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.862540 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:16.001286 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.139s	user 0.094s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":10028,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22218,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2000}
I20260812 06:17:16.001842 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:16.032272 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.030s	user 0.019s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12410,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.032792 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:16.129894 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.097s	user 0.070s	sys 0.025s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":198,"lbm_read_time_us":5618,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17876,"lbm_writes_lt_1ms":343,"mutex_wait_us":30,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":1500}
I20260812 06:17:16.130529 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=10.126437
I20260812 06:17:16.181694 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.051s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18322,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.182301 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:16.197523 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.198132 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushMRSOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:16.223965 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushMRSOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":281,"dirs.run_wall_time_us":1261,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1553,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:16.224651 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1): free 117302588 bytes of WAL
I20260812 06:17:16.224869 15782 log_reader.cc:385] T d1079cb1b04d4afdae46ff21cdc49cf1: removed 12 log segments from log reader
I20260812 06:17:16.224915 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000016 (ops 75-79)
I20260812 06:17:16.224946 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000017 (ops 80-84)
I20260812 06:17:16.224975 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000018 (ops 85-89)
I20260812 06:17:16.225008 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000019 (ops 90-94)
I20260812 06:17:16.225037 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000020 (ops 95-98)
I20260812 06:17:16.225069 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000021 (ops 99-103)
I20260812 06:17:16.225100 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000022 (ops 104-108)
I20260812 06:17:16.225131 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000023 (ops 109-113)
I20260812 06:17:16.225163 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000024 (ops 114-118)
I20260812 06:17:16.225193 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000025 (ops 119-122)
I20260812 06:17:16.225224 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000026 (ops 123-127)
I20260812 06:17:16.225255 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000027 (ops 128-132)
I20260812 06:17:16.245647 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.021s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:17:16.246153 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling UndoDeltaBlockGCOp(d1079cb1b04d4afdae46ff21cdc49cf1): 473 bytes on disk
I20260812 06:17:16.246680 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: UndoDeltaBlockGCOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.247282 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=3.181125
I20260812 06:17:16.269284 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.022s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6484,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:16.269809 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:16.279242 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3241,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.279731 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:16.452286 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.172s	user 0.114s	sys 0.054s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2391,"lbm_read_time_us":11395,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33543,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:17:16.452824 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=14.095187
I20260812 06:17:16.499456 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.046s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18354,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.500069 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:16.515373 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.515903 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:16.662810 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.147s	user 0.104s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":8892,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26872,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:17:16.663671 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=12.110812
I20260812 06:17:16.702811 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.039s	user 0.022s	sys 0.016s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":15218,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":332,"reinsert_count":0,"update_count":1650}
I20260812 06:17:16.703452 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:16.724593 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.021s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":3504,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:17:16.725054 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:16.734326 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3249,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.734776 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:16.901330 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.166s	user 0.104s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774772,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":677,"lbm_read_time_us":11288,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27337,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:16.901857 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=14.095187
I20260812 06:17:16.960191 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.058s	user 0.032s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19107,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.960813 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:16.975898 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5755,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.976387 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:17.135712 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.159s	user 0.114s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":608,"lbm_read_time_us":10029,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27086,"lbm_writes_lt_1ms":543,"mutex_wait_us":283,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:17.136287 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=14.095187
I20260812 06:17:17.190196 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.054s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17662,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.190732 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:17.201313 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.201897 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:17.386114 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.184s	user 0.122s	sys 0.053s 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":606,"lbm_read_time_us":12721,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29498,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:17:17.386667 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=14.095187
I20260812 06:17:17.436975 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.050s	user 0.021s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16536,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.437660 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:17.448763 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.449247 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:17.622059 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.173s	user 0.108s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":517,"lbm_read_time_us":11961,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28043,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:17:17.622582 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=11.118625
I20260812 06:17:17.656756 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.034s	user 0.026s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13936,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:17.657317 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:17.682339 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.025s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5262,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.682861 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:17.699760 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.017s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3568,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.700300 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushMRSOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:17.741618 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushMRSOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.041s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1484,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1560,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:17.742460 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1): free 136728519 bytes of WAL
I20260812 06:17:17.742712 15782 log_reader.cc:385] T d1079cb1b04d4afdae46ff21cdc49cf1: removed 13 log segments from log reader
I20260812 06:17:17.742774 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000028 (ops 133-137)
I20260812 06:17:17.742823 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000029 (ops 138-142)
I20260812 06:17:17.742856 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000030 (ops 143-147)
I20260812 06:17:17.742877 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000031 (ops 148-152)
I20260812 06:17:17.742904 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000032 (ops 153-157)
I20260812 06:17:17.742933 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000033 (ops 158-162)
I20260812 06:17:17.742964 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000034 (ops 163-167)
I20260812 06:17:17.742992 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000035 (ops 168-172)
I20260812 06:17:17.743019 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000036 (ops 173-177)
I20260812 06:17:17.743047 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000037 (ops 178-182)
I20260812 06:17:17.743072 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000038 (ops 183-187)
I20260812 06:17:17.743103 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000039 (ops 188-192)
I20260812 06:17:17.743131 15782 log.cc:1079] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/d1079cb1b04d4afdae46ff21cdc49cf1/wal-000000040 (ops 193-197)
I20260812 06:17:17.772012 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: LogGCOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:17.772413 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:17.786798 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":3997,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:17:17.787252 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling UndoDeltaBlockGCOp(d1079cb1b04d4afdae46ff21cdc49cf1): 492 bytes on disk
I20260812 06:17:17.787655 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: UndoDeltaBlockGCOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.788163 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=2.188937
I20260812 06:17:17.798045 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: FlushDeltaMemStoresOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4061633,"delete_count":0,"lbm_write_time_us":3482,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:17:17.798552 15896 maintenance_manager.cc:419] P 056c855323454e619eed2360635c0d1c: Scheduling MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1): perf score=1.000000
I20260812 06:17:17.834910 15594 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.697s	user 1.715s	sys 0.108s
I20260812 06:17:17.942734 15594 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.107s	user 0.003s	sys 0.000s
I20260812 06:17:17.943419 15594 tablet_server.cc:179] TabletServer@127.15.58.129:0 shutting down...
I20260812 06:17:17.987654 15782 maintenance_manager.cc:643] P 056c855323454e619eed2360635c0d1c: MajorDeltaCompactionOp(d1079cb1b04d4afdae46ff21cdc49cf1) complete. Timing: real 0.189s	user 0.119s	sys 0.070s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979860,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":504,"lbm_read_time_us":15309,"lbm_reads_lt_1ms":771,"lbm_write_time_us":29033,"lbm_writes_lt_1ms":743,"mutex_wait_us":49,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":33152,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:17:17.988814 15594 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:17.989362 15594 tablet_replica.cc:333] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c: stopping tablet replica
I20260812 06:17:17.989598 15594 raft_consensus.cc:2243] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:17.989825 15594 raft_consensus.cc:2272] T d1079cb1b04d4afdae46ff21cdc49cf1 P 056c855323454e619eed2360635c0d1c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:17.996222 15594 tablet_server.cc:196] TabletServer@127.15.58.129:0 shutdown complete.
I20260812 06:17:18.046543 15594 master.cc:562] Master@127.15.58.190:46833 shutting down...
I20260812 06:17:18.050248 15594 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:18.050436 15594 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:18.050491 15594 tablet_replica.cc:333] T 00000000000000000000000000000000 P c34df88bf5d74ea58cadae4175799392: stopping tablet replica
I20260812 06:17:18.062882 15594 master.cc:584] Master@127.15.58.190:46833 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5317 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:18.141767 15594 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.58.190:34915
I20260812 06:17:18.142198 15594 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:18.144125 15951 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:17:18.144282 15594 server_base.cc:1061] running on GCE node
W20260812 06:17:18.144327 15952 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:17:18.144232 15954 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:17:18.144599 15594 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:18.144641 15594 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:17:18.144655 15594 hybrid_clock.cc:648] HybridClock initialized: now 1786515438144656 us; error 0 us; skew 500 ppm
I20260812 06:17:18.145437 15594 webserver.cc:533] Webserver started at http://127.15.58.190:39947/ using document root <none> and password file <none>
I20260812 06:17:18.145596 15594 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:18.145635 15594 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:18.145692 15594 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:18.146073 15594 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/master-0-root/instance:
uuid: "eeb8ab81a6a942f7b93205ae129ac704"
format_stamp: "Formatted at 2026-08-12 06:17:18 on dist-test-slave-vpvm"
I20260812 06:17:18.147487 15594 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:18.148394 15965 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:17:18.148618 15594 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:18.148686 15594 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/master-0-root
uuid: "eeb8ab81a6a942f7b93205ae129ac704"
format_stamp: "Formatted at 2026-08-12 06:17:18 on dist-test-slave-vpvm"
I20260812 06:17:18.148756 15594 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-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:17:18.154012 15594 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:18.154325 15594 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:18.158283 15594 rpc_server.cc:307] RPC server started. Bound to: 127.15.58.190:34915
I20260812 06:17:18.166067 16060 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.58.190:34915 every 8 connection(s)
I20260812 06:17:18.166567 16061 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:17:18.168331 16061 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704: Bootstrap starting.
I20260812 06:17:18.169147 16061 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:18.170197 16061 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704: No bootstrap required, opened a new log
I20260812 06:17:18.170603 16061 raft_consensus.cc:359] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb8ab81a6a942f7b93205ae129ac704" member_type: VOTER }
I20260812 06:17:18.170687 16061 raft_consensus.cc:385] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:18.170718 16061 raft_consensus.cc:740] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: eeb8ab81a6a942f7b93205ae129ac704, State: Initialized, Role: FOLLOWER
I20260812 06:17:18.170866 16061 consensus_queue.cc:260] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [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: "eeb8ab81a6a942f7b93205ae129ac704" member_type: VOTER }
I20260812 06:17:18.170948 16061 raft_consensus.cc:399] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:18.170985 16061 raft_consensus.cc:493] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:18.171036 16061 raft_consensus.cc:3060] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:18.171694 16061 raft_consensus.cc:515] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb8ab81a6a942f7b93205ae129ac704" member_type: VOTER }
I20260812 06:17:18.171813 16061 leader_election.cc:304] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [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: eeb8ab81a6a942f7b93205ae129ac704; no voters: 
I20260812 06:17:18.171993 16061 leader_election.cc:290] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:18.172122 16064 raft_consensus.cc:2804] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:18.172307 16064 raft_consensus.cc:697] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 1 LEADER]: Becoming Leader. State: Replica: eeb8ab81a6a942f7b93205ae129ac704, State: Running, Role: LEADER
I20260812 06:17:18.172456 16061 sys_catalog.cc:565] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:18.172434 16064 consensus_queue.cc:237] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [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: "eeb8ab81a6a942f7b93205ae129ac704" member_type: VOTER }
I20260812 06:17:18.172870 16066 sys_catalog.cc:455] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [sys.catalog]: SysCatalogTable state changed. Reason: New leader eeb8ab81a6a942f7b93205ae129ac704. Latest consensus state: current_term: 1 leader_uuid: "eeb8ab81a6a942f7b93205ae129ac704" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb8ab81a6a942f7b93205ae129ac704" member_type: VOTER } }
I20260812 06:17:18.172899 16065 sys_catalog.cc:455] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "eeb8ab81a6a942f7b93205ae129ac704" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb8ab81a6a942f7b93205ae129ac704" member_type: VOTER } }
I20260812 06:17:18.173053 16065 sys_catalog.cc:458] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:18.173043 16066 sys_catalog.cc:458] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:18.173630 16071 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:18.174453 16071 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:18.174666 15594 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:18.176213 16071 catalog_manager.cc:1383] Generated new cluster ID: 2d06ffbfedba469399394d6bf4465743
I20260812 06:17:18.176262 16071 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:18.197664 16071 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:18.198289 16071 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:18.202394 16071 catalog_manager.cc:6092] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704: Generated new TSK 0
I20260812 06:17:18.202564 16071 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:18.206912 15594 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:18.208694 16101 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:17:18.208861 16104 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:17:18.208899 15594 server_base.cc:1061] running on GCE node
W20260812 06:17:18.208982 16102 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:17:18.209203 15594 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:18.209260 15594 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:17:18.209276 15594 hybrid_clock.cc:648] HybridClock initialized: now 1786515438209276 us; error 0 us; skew 500 ppm
I20260812 06:17:18.210115 15594 webserver.cc:533] Webserver started at http://127.15.58.129:35493/ using document root <none> and password file <none>
I20260812 06:17:18.210263 15594 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:18.210312 15594 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:18.210366 15594 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:18.210757 15594 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/instance:
uuid: "c34021932b894e72a5517c5250b0f4e1"
format_stamp: "Formatted at 2026-08-12 06:17:18 on dist-test-slave-vpvm"
I20260812 06:17:18.212250 15594 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:18.213272 16116 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:17:18.213560 15594 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:18.213634 15594 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root
uuid: "c34021932b894e72a5517c5250b0f4e1"
format_stamp: "Formatted at 2026-08-12 06:17:18 on dist-test-slave-vpvm"
I20260812 06:17:18.213708 15594 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-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:17:18.224058 15594 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:18.224460 15594 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:18.224758 15594 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:18.225231 15594 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:18.225273 15594 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:18.225318 15594 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:18.225344 15594 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:18.229530 15594 rpc_server.cc:307] RPC server started. Bound to: 127.15.58.129:40945
I20260812 06:17:18.229571 16240 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.58.129:40945 every 8 connection(s)
I20260812 06:17:18.237059 16241 heartbeater.cc:344] Connected to a master server at 127.15.58.190:34915
I20260812 06:17:18.237191 16241 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:18.237433 16241 heartbeater.cc:507] Master 127.15.58.190:34915 requested a full tablet report, sending...
I20260812 06:17:18.238211 15997 ts_manager.cc:194] Registered new tserver with Master: c34021932b894e72a5517c5250b0f4e1 (127.15.58.129:40945)
I20260812 06:17:18.238775 15594 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008840852s
I20260812 06:17:18.239063 15997 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52536
I20260812 06:17:18.246695 15997 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52540:
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:17:18.258251 16169 tablet_service.cc:1511] Processing CreateTablet for tablet 27e2190bc0fa402493f56e97024df093 (DEFAULT_TABLE table=heavy-update-compaction-test [id=42bdba952ee9478891649473717a5d1d]), partition=
I20260812 06:17:18.258555 16169 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 27e2190bc0fa402493f56e97024df093. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:18.260731 16263 tablet_bootstrap.cc:492] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Bootstrap starting.
I20260812 06:17:18.261586 16263 tablet_bootstrap.cc:654] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:18.262750 16263 tablet_bootstrap.cc:492] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: No bootstrap required, opened a new log
I20260812 06:17:18.262831 16263 ts_tablet_manager.cc:1403] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:18.263265 16263 raft_consensus.cc:359] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c34021932b894e72a5517c5250b0f4e1" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 40945 } }
I20260812 06:17:18.263360 16263 raft_consensus.cc:385] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:18.263381 16263 raft_consensus.cc:740] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c34021932b894e72a5517c5250b0f4e1, State: Initialized, Role: FOLLOWER
I20260812 06:17:18.263494 16263 consensus_queue.cc:260] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [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: "c34021932b894e72a5517c5250b0f4e1" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 40945 } }
I20260812 06:17:18.263583 16263 raft_consensus.cc:399] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:18.263617 16263 raft_consensus.cc:493] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:18.263665 16263 raft_consensus.cc:3060] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:18.264376 16263 raft_consensus.cc:515] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c34021932b894e72a5517c5250b0f4e1" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 40945 } }
I20260812 06:17:18.264500 16263 leader_election.cc:304] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [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: c34021932b894e72a5517c5250b0f4e1; no voters: 
I20260812 06:17:18.264701 16263 leader_election.cc:290] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:18.264822 16265 raft_consensus.cc:2804] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:18.264998 16263 ts_tablet_manager.cc:1434] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:18.265034 16241 heartbeater.cc:499] Master 127.15.58.190:34915 was elected leader, sending a full tablet report...
I20260812 06:17:18.265034 16265 raft_consensus.cc:697] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 1 LEADER]: Becoming Leader. State: Replica: c34021932b894e72a5517c5250b0f4e1, State: Running, Role: LEADER
I20260812 06:17:18.265239 16265 consensus_queue.cc:237] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [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: "c34021932b894e72a5517c5250b0f4e1" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 40945 } }
I20260812 06:17:18.266667 15994 catalog_manager.cc:5719] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 reported cstate change: term changed from 0 to 1, leader changed from <none> to c34021932b894e72a5517c5250b0f4e1 (127.15.58.129). New cstate: current_term: 1 leader_uuid: "c34021932b894e72a5517c5250b0f4e1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c34021932b894e72a5517c5250b0f4e1" member_type: VOTER last_known_addr { host: "127.15.58.129" port: 40945 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:18.325588 15594 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.016s	sys 0.006s
I20260812 06:17:18.480551 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushMRSOp(27e2190bc0fa402493f56e97024df093): perf score=19.054940
I20260812 06:17:18.630122 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushMRSOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.149s	user 0.108s	sys 0.040s Metrics: {"bytes_written":12799784,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":172,"dirs.run_wall_time_us":890,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35537,"lbm_writes_lt_1ms":779,"mutex_wait_us":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1536,"update_count":1560}
I20260812 06:17:18.630790 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling LogGCOp(27e2190bc0fa402493f56e97024df093): free 20743880 bytes of WAL
I20260812 06:17:18.631042 16130 log_reader.cc:385] T 27e2190bc0fa402493f56e97024df093: removed 2 log segments from log reader
I20260812 06:17:18.631115 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000001 (ops 1-6)
I20260812 06:17:18.631223 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000002 (ops 7-11)
I20260812 06:17:18.635154 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: LogGCOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:18.635510 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling UndoDeltaBlockGCOp(27e2190bc0fa402493f56e97024df093): 16821646 bytes on disk
I20260812 06:17:18.635913 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: UndoDeltaBlockGCOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.636314 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:18.656111 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.020s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3610359,"delete_count":0,"lbm_write_time_us":3362,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:17:18.656554 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:18.665654 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3233,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.666225 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:18.832958 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.167s	user 0.121s	sys 0.033s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405543,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":505,"lbm_read_time_us":11053,"lbm_reads_lt_1ms":559,"lbm_write_time_us":27210,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":4352,"thread_start_us":314,"threads_started":5,"update_count":2450}
I20260812 06:17:18.833554 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:18.880334 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.047s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18010,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.880904 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:18.896456 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5730,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.897056 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:19.070418 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.173s	user 0.112s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":704,"lbm_read_time_us":11841,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29550,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:17:19.070983 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:19.116583 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.045s	user 0.024s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16656,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.117136 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:19.256536 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.139s	user 0.092s	sys 0.039s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":817,"lbm_read_time_us":11161,"lbm_reads_lt_1ms":463,"lbm_write_time_us":19663,"lbm_writes_lt_1ms":443,"mutex_wait_us":241,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2000}
I20260812 06:17:19.257032 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:19.303229 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.046s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17090,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.303761 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:19.319864 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.320487 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:19.491097 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.170s	user 0.107s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":442,"lbm_read_time_us":9567,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24537,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":61952,"update_count":2500}
I20260812 06:17:19.491673 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:19.544342 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.053s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21407,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.544936 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:19.555943 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.556528 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:19.700203 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.143s	user 0.109s	sys 0.026s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":10050,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26505,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:17:19.700755 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=11.118625
I20260812 06:17:19.736245 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.035s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14417,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:19.736907 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:19.761439 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.024s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4664,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.761994 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:19.771953 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.772445 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushMRSOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:19.800232 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushMRSOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.028s	user 0.022s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1374,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1631,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:19.800832 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling LogGCOp(27e2190bc0fa402493f56e97024df093): free 115943172 bytes of WAL
I20260812 06:17:19.801072 16130 log_reader.cc:385] T 27e2190bc0fa402493f56e97024df093: removed 11 log segments from log reader
I20260812 06:17:19.801131 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000003 (ops 12-16)
I20260812 06:17:19.801174 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000004 (ops 17-21)
I20260812 06:17:19.801204 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000005 (ops 22-26)
I20260812 06:17:19.801234 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000006 (ops 27-31)
I20260812 06:17:19.801267 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000007 (ops 32-36)
I20260812 06:17:19.801299 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000008 (ops 37-41)
I20260812 06:17:19.801327 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000009 (ops 42-46)
I20260812 06:17:19.801353 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000010 (ops 47-51)
I20260812 06:17:19.801383 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000011 (ops 52-56)
I20260812 06:17:19.801414 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000012 (ops 57-61)
I20260812 06:17:19.801443 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000013 (ops 62-66)
I20260812 06:17:19.827376 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: LogGCOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.026s	user 0.003s	sys 0.020s Metrics: {}
I20260812 06:17:19.827839 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling UndoDeltaBlockGCOp(27e2190bc0fa402493f56e97024df093): 447 bytes on disk
I20260812 06:17:19.828271 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: UndoDeltaBlockGCOp(27e2190bc0fa402493f56e97024df093) 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:17:19.828820 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=3.181125
I20260812 06:17:19.852214 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.023s	user 0.010s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:19.852741 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:19.862627 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3624,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.863207 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:20.083189 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.220s	user 0.156s	sys 0.064s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020845,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":195,"lbm_read_time_us":14878,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37362,"lbm_writes_lt_1ms":743,"mutex_wait_us":42,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:17:20.083729 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:20.132834 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.049s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16491953,"delete_count":0,"lbm_write_time_us":21761,"lbm_writes_lt_1ms":405,"reinsert_count":0,"update_count":2010}
I20260812 06:17:20.133488 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:20.146425 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4486,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:20.146979 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:20.319476 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.172s	user 0.100s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":717,"lbm_read_time_us":11124,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27713,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:20.319944 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:20.376521 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.056s	user 0.029s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17829,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.377089 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:20.387542 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3875,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.387982 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:20.563823 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.176s	user 0.095s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":134,"lbm_read_time_us":11802,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27680,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":43008,"update_count":2500}
I20260812 06:17:20.564427 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:20.608069 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.043s	user 0.022s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17333,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.608632 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:20.627122 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.018s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.627749 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:20.806561 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.179s	user 0.098s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":118,"lbm_read_time_us":12182,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25229,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:17:20.807215 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:20.861135 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.054s	user 0.014s	sys 0.028s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19990,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.861595 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:20.871632 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3661,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.872247 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:21.036459 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.164s	user 0.104s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":508,"lbm_read_time_us":10679,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27022,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:17:21.037024 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=11.118625
I20260812 06:17:21.066156 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.029s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":11389,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:21.066797 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:21.090857 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.024s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4614,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:21.091332 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:21.101604 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3777,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.102160 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:21.250526 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.148s	user 0.127s	sys 0.016s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":608,"lbm_read_time_us":9327,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26703,"lbm_writes_lt_1ms":543,"mutex_wait_us":308,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:17:21.251157 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=11.118625
I20260812 06:17:21.287602 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.036s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14633,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:21.288197 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:21.311604 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.023s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3822,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:21.312126 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:21.322666 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.323215 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushMRSOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:21.352903 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushMRSOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":45,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1153,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1630,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:21.353757 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling LogGCOp(27e2190bc0fa402493f56e97024df093): free 129773570 bytes of WAL
I20260812 06:17:21.354043 16130 log_reader.cc:385] T 27e2190bc0fa402493f56e97024df093: removed 13 log segments from log reader
I20260812 06:17:21.354094 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000014 (ops 67-71)
I20260812 06:17:21.354137 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000015 (ops 72-76)
I20260812 06:17:21.354171 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000016 (ops 77-81)
I20260812 06:17:21.354202 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000017 (ops 82-86)
I20260812 06:17:21.354233 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000018 (ops 87-91)
I20260812 06:17:21.354264 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000019 (ops 92-96)
I20260812 06:17:21.354293 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000020 (ops 97-101)
I20260812 06:17:21.354322 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000021 (ops 102-106)
I20260812 06:17:21.354351 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000022 (ops 107-111)
I20260812 06:17:21.354380 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000023 (ops 112-116)
I20260812 06:17:21.354410 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000024 (ops 117-120)
I20260812 06:17:21.354440 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000025 (ops 121-125)
I20260812 06:17:21.354471 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000026 (ops 126-130)
I20260812 06:17:21.376726 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: LogGCOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.023s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:17:21.377223 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling UndoDeltaBlockGCOp(27e2190bc0fa402493f56e97024df093): 493 bytes on disk
I20260812 06:17:21.377678 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: UndoDeltaBlockGCOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:21.378355 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=3.181125
I20260812 06:17:21.398387 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.020s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:21.398967 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:21.413254 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5309,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:21.413806 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:21.634258 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.220s	user 0.132s	sys 0.086s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020847,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":253,"lbm_read_time_us":15512,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36877,"lbm_writes_lt_1ms":743,"mutex_wait_us":41,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:17:21.634737 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:21.683079 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.048s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22225,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.683677 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:21.699155 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5796,"lbm_writes_lt_1ms":103,"mutex_wait_us":50,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.699678 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:21.872087 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.172s	user 0.106s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":13123,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26721,"lbm_writes_lt_1ms":543,"mutex_wait_us":99,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:17:21.872717 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:21.930708 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.057s	user 0.034s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19316,"lbm_writes_lt_1ms":403,"mutex_wait_us":2,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.931254 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:21.941816 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.942305 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:22.105114 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.163s	user 0.120s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":697,"lbm_read_time_us":12481,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24474,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:17:22.105772 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=11.118625
I20260812 06:17:22.147241 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.041s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17173,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:22.147876 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:22.178653 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.031s	user 0.003s	sys 0.016s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.179299 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:22.189819 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.190449 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:22.370054 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.179s	user 0.129s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":725,"lbm_read_time_us":12564,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28464,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:22.370610 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=11.118625
I20260812 06:17:22.412945 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.042s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18590,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:22.413453 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:22.428532 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3670,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.429061 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:22.438196 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3065,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.438767 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:22.614683 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.176s	user 0.127s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":520,"lbm_read_time_us":9735,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27883,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:22.617911 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:22.665469 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.047s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19592,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.665970 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:22.676093 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.676667 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:22.833987 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.157s	user 0.118s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":960,"lbm_read_time_us":9364,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28803,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2500}
I20260812 06:17:22.834581 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=14.095187
I20260812 06:17:22.881831 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.047s	user 0.014s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16373,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.882470 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:22.897306 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.015s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.897980 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushMRSOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:22.932379 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushMRSOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1870,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:22.933105 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling LogGCOp(27e2190bc0fa402493f56e97024df093): free 133024646 bytes of WAL
I20260812 06:17:22.933326 16130 log_reader.cc:385] T 27e2190bc0fa402493f56e97024df093: removed 13 log segments from log reader
I20260812 06:17:22.933372 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000027 (ops 131-135)
I20260812 06:17:22.933400 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000028 (ops 136-140)
I20260812 06:17:22.933432 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000029 (ops 141-145)
I20260812 06:17:22.933456 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000030 (ops 146-150)
I20260812 06:17:22.933488 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000031 (ops 151-155)
I20260812 06:17:22.933521 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000032 (ops 156-160)
I20260812 06:17:22.933560 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000033 (ops 161-165)
I20260812 06:17:22.933593 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000034 (ops 166-170)
I20260812 06:17:22.933624 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000035 (ops 171-174)
I20260812 06:17:22.933655 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000036 (ops 175-179)
I20260812 06:17:22.933686 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000037 (ops 180-184)
I20260812 06:17:22.933718 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000038 (ops 185-189)
I20260812 06:17:22.933750 16130 log.cc:1079] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: Deleting log segment in path: /tmp/dist-test-task1IRPhT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515432804035-15594-0/minicluster-data/ts-0-root/wals/27e2190bc0fa402493f56e97024df093/wal-000000039 (ops 190-194)
I20260812 06:17:22.957311 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: LogGCOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:22.957697 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=3.181125
I20260812 06:17:22.977305 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.019s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4553932,"delete_count":0,"lbm_write_time_us":4108,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:17:22.978000 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093): perf score=2.188937
I20260812 06:17:22.992182 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: FlushDeltaMemStoresOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":5374,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:22.992782 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling UndoDeltaBlockGCOp(27e2190bc0fa402493f56e97024df093): 492 bytes on disk
I20260812 06:17:22.993285 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: UndoDeltaBlockGCOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:22.993875 16242 maintenance_manager.cc:419] P c34021932b894e72a5517c5250b0f4e1: Scheduling MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093): perf score=1.000000
I20260812 06:17:23.044952 15594 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.719s	user 1.731s	sys 0.192s
I20260812 06:17:23.141106 15594 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.096s	user 0.001s	sys 0.000s
I20260812 06:17:23.141641 15594 tablet_server.cc:179] TabletServer@127.15.58.129:0 shutting down...
I20260812 06:17:23.185410 16130 maintenance_manager.cc:643] P c34021932b894e72a5517c5250b0f4e1: MajorDeltaCompactionOp(27e2190bc0fa402493f56e97024df093) complete. Timing: real 0.191s	user 0.126s	sys 0.065s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020740,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":600,"lbm_read_time_us":15689,"lbm_reads_lt_1ms":770,"lbm_write_time_us":29926,"lbm_writes_lt_1ms":743,"mutex_wait_us":95,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5632,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:17:23.186663 15594 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:23.186885 15594 tablet_replica.cc:333] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1: stopping tablet replica
I20260812 06:17:23.187037 15594 raft_consensus.cc:2243] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:23.187204 15594 raft_consensus.cc:2272] T 27e2190bc0fa402493f56e97024df093 P c34021932b894e72a5517c5250b0f4e1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:23.202306 15594 tablet_server.cc:196] TabletServer@127.15.58.129:0 shutdown complete.
I20260812 06:17:23.243494 15594 master.cc:562] Master@127.15.58.190:34915 shutting down...
I20260812 06:17:23.246906 15594 raft_consensus.cc:2243] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:23.247110 15594 raft_consensus.cc:2272] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:23.247186 15594 tablet_replica.cc:333] T 00000000000000000000000000000000 P eeb8ab81a6a942f7b93205ae129ac704: stopping tablet replica
I20260812 06:17:23.259496 15594 master.cc:584] Master@127.15.58.190:34915 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5195 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10513 ms total)

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