[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:14.902973 18627 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.48.254:43875
I20260812 06:18:14.904012 18627 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:14.904634 18627 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.912592 18634 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:14.912694 18637 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:14.912592 18640 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:14.913359 18627 server_base.cc:1061] running on GCE node
I20260812 06:18:14.913941 18627 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.914086 18627 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:14.914143 18627 hybrid_clock.cc:648] HybridClock initialized: now 1786515494914140 us; error 0 us; skew 500 ppm
I20260812 06:18:14.916293 18627 webserver.cc:533] Webserver started at http://127.18.48.254:40961/ using document root <none> and password file <none>
I20260812 06:18:14.916913 18627 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.917012 18627 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.917280 18627 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.919247 18627 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/master-0-root/instance:
uuid: "38880994ee884debb5ee482087c8f266"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-tk9z"
I20260812 06:18:14.923007 18627 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:14.925565 18650 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.926765 18627 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:14.926905 18627 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/master-0-root
uuid: "38880994ee884debb5ee482087c8f266"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-tk9z"
I20260812 06:18:14.927016 18627 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:14.953104 18627 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.953848 18627 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:14.954053 18627 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.962308 18627 rpc_server.cc:307] RPC server started. Bound to: 127.18.48.254:43875
I20260812 06:18:14.962316 18746 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.48.254:43875 every 8 connection(s)
I20260812 06:18:14.964756 18747 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:14.970623 18747 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266: Bootstrap starting.
I20260812 06:18:14.973110 18747 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.974088 18747 log.cc:826] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:14.975983 18747 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266: No bootstrap required, opened a new log
I20260812 06:18:14.978994 18747 raft_consensus.cc:359] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38880994ee884debb5ee482087c8f266" member_type: VOTER }
I20260812 06:18:14.979174 18747 raft_consensus.cc:385] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.979246 18747 raft_consensus.cc:740] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 38880994ee884debb5ee482087c8f266, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.979903 18747 consensus_queue.cc:260] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [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: "38880994ee884debb5ee482087c8f266" member_type: VOTER }
I20260812 06:18:14.980077 18747 raft_consensus.cc:399] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.980157 18747 raft_consensus.cc:493] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.980337 18747 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.981208 18747 raft_consensus.cc:515] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38880994ee884debb5ee482087c8f266" member_type: VOTER }
I20260812 06:18:14.981675 18747 leader_election.cc:304] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [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: 38880994ee884debb5ee482087c8f266; no voters: 
I20260812 06:18:14.982064 18747 leader_election.cc:290] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.982307 18750 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.982645 18750 raft_consensus.cc:697] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 1 LEADER]: Becoming Leader. State: Replica: 38880994ee884debb5ee482087c8f266, State: Running, Role: LEADER
I20260812 06:18:14.983050 18750 consensus_queue.cc:237] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [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: "38880994ee884debb5ee482087c8f266" member_type: VOTER }
I20260812 06:18:14.983167 18747 sys_catalog.cc:565] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:14.985169 18756 sys_catalog.cc:455] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 38880994ee884debb5ee482087c8f266. Latest consensus state: current_term: 1 leader_uuid: "38880994ee884debb5ee482087c8f266" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38880994ee884debb5ee482087c8f266" member_type: VOTER } }
I20260812 06:18:14.985220 18751 sys_catalog.cc:455] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "38880994ee884debb5ee482087c8f266" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38880994ee884debb5ee482087c8f266" member_type: VOTER } }
I20260812 06:18:14.985323 18756 sys_catalog.cc:458] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.985343 18751 sys_catalog.cc:458] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.985685 18780 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:14.985805 18627 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:14.988207 18780 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:14.993100 18780 catalog_manager.cc:1383] Generated new cluster ID: a7de6f97129d470c9cafeb89f088e319
I20260812 06:18:14.993177 18780 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:15.001276 18780 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:15.002239 18780 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:15.012210 18780 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266: Generated new TSK 0
I20260812 06:18:15.012965 18780 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:15.018524 18627 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:15.021967 18792 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:15.022001 18795 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:15.022022 18627 server_base.cc:1061] running on GCE node
W20260812 06:18:15.022209 18791 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:15.022485 18627 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:15.022534 18627 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:15.022552 18627 hybrid_clock.cc:648] HybridClock initialized: now 1786515495022552 us; error 0 us; skew 500 ppm
I20260812 06:18:15.023552 18627 webserver.cc:533] Webserver started at http://127.18.48.193:35707/ using document root <none> and password file <none>
I20260812 06:18:15.023753 18627 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:15.023830 18627 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:15.023932 18627 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:15.024385 18627 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/instance:
uuid: "4d69ae9b62ec437180f325c69bb92948"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-tk9z"
I20260812 06:18:15.026058 18627 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:15.027285 18802 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:15.027617 18627 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:15.027695 18627 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root
uuid: "4d69ae9b62ec437180f325c69bb92948"
format_stamp: "Formatted at 2026-08-12 06:18:15 on dist-test-slave-tk9z"
I20260812 06:18:15.027798 18627 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:15.052613 18627 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:15.053170 18627 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:15.053779 18627 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:15.054795 18627 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:15.054857 18627 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:15.054940 18627 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:15.054986 18627 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:15.062691 18627 rpc_server.cc:307] RPC server started. Bound to: 127.18.48.193:43081
I20260812 06:18:15.062744 18905 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.48.193:43081 every 8 connection(s)
I20260812 06:18:15.074205 18906 heartbeater.cc:344] Connected to a master server at 127.18.48.254:43875
I20260812 06:18:15.074508 18906 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:15.075067 18906 heartbeater.cc:507] Master 127.18.48.254:43875 requested a full tablet report, sending...
I20260812 06:18:15.076664 18675 ts_manager.cc:194] Registered new tserver with Master: 4d69ae9b62ec437180f325c69bb92948 (127.18.48.193:43081)
I20260812 06:18:15.077049 18627 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013631725s
I20260812 06:18:15.077912 18675 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45586
I20260812 06:18:15.087281 18675 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45602:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:15.102600 18850 tablet_service.cc:1511] Processing CreateTablet for tablet 8809c974149049d49247ca6b5727cf48 (DEFAULT_TABLE table=heavy-update-compaction-test [id=792f8c24176c4973b466e679497415b7]), partition=
I20260812 06:18:15.103137 18850 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8809c974149049d49247ca6b5727cf48. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:15.106027 18927 tablet_bootstrap.cc:492] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Bootstrap starting.
I20260812 06:18:15.107142 18927 tablet_bootstrap.cc:654] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:15.108460 18927 tablet_bootstrap.cc:492] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: No bootstrap required, opened a new log
I20260812 06:18:15.108609 18927 ts_tablet_manager.cc:1403] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:15.109221 18927 raft_consensus.cc:359] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d69ae9b62ec437180f325c69bb92948" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 43081 } }
I20260812 06:18:15.109371 18927 raft_consensus.cc:385] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:15.109462 18927 raft_consensus.cc:740] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4d69ae9b62ec437180f325c69bb92948, State: Initialized, Role: FOLLOWER
I20260812 06:18:15.109728 18927 consensus_queue.cc:260] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [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: "4d69ae9b62ec437180f325c69bb92948" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 43081 } }
I20260812 06:18:15.109855 18927 raft_consensus.cc:399] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:15.109928 18927 raft_consensus.cc:493] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:15.110003 18927 raft_consensus.cc:3060] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:15.111402 18927 raft_consensus.cc:515] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d69ae9b62ec437180f325c69bb92948" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 43081 } }
I20260812 06:18:15.111579 18927 leader_election.cc:304] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [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: 4d69ae9b62ec437180f325c69bb92948; no voters: 
I20260812 06:18:15.111881 18927 leader_election.cc:290] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:15.111980 18929 raft_consensus.cc:2804] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:15.112195 18929 raft_consensus.cc:697] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 1 LEADER]: Becoming Leader. State: Replica: 4d69ae9b62ec437180f325c69bb92948, State: Running, Role: LEADER
I20260812 06:18:15.112306 18927 ts_tablet_manager.cc:1434] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Time spent starting tablet: real 0.004s	user 0.001s	sys 0.002s
I20260812 06:18:15.112440 18929 consensus_queue.cc:237] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [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: "4d69ae9b62ec437180f325c69bb92948" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 43081 } }
I20260812 06:18:15.112619 18906 heartbeater.cc:499] Master 127.18.48.254:43875 was elected leader, sending a full tablet report...
I20260812 06:18:15.115516 18675 catalog_manager.cc:5719] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4d69ae9b62ec437180f325c69bb92948 (127.18.48.193). New cstate: current_term: 1 leader_uuid: "4d69ae9b62ec437180f325c69bb92948" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d69ae9b62ec437180f325c69bb92948" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 43081 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:15.182686 18627 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.026s	sys 0.003s
I20260812 06:18:15.314065 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushMRSOp(8809c974149049d49247ca6b5727cf48): perf score=19.054940
I20260812 06:18:15.494946 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushMRSOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.180s	user 0.164s	sys 0.016s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":204,"delete_count":0,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":826,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45709,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":136,"threads_started":1,"update_count":1500}
I20260812 06:18:15.496309 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling LogGCOp(8809c974149049d49247ca6b5727cf48): free 20743880 bytes of WAL
I20260812 06:18:15.496711 18808 log_reader.cc:385] T 8809c974149049d49247ca6b5727cf48: removed 2 log segments from log reader
I20260812 06:18:15.496836 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000001 (ops 1-6)
I20260812 06:18:15.496949 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000002 (ops 7-11)
I20260812 06:18:15.502653 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: LogGCOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:18:15.503082 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:15.530934 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.028s	user 0.013s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.531548 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling UndoDeltaBlockGCOp(8809c974149049d49247ca6b5727cf48): 16411393 bytes on disk
I20260812 06:18:15.532202 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: UndoDeltaBlockGCOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:18:15.532645 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:15.548388 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.549041 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:15.725433 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.176s	user 0.124s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":634,"lbm_read_time_us":13381,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28952,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":319,"threads_started":5,"update_count":2500}
I20260812 06:18:15.725930 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:15.772500 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.046s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17383,"lbm_writes_lt_1ms":303,"mutex_wait_us":3,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":1500}
I20260812 06:18:15.773046 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:15.784416 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4231,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.785218 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:15.920290 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.135s	user 0.106s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":291,"lbm_read_time_us":9601,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24405,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:18:15.920935 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:15.967461 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.046s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18109,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.967921 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:15.978494 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4036,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.978961 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:16.108611 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.129s	user 0.117s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":9963,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24069,"lbm_writes_lt_1ms":443,"mutex_wait_us":88,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23296,"update_count":2000}
I20260812 06:18:16.109329 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:16.157262 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.048s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17570,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.157856 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:16.171283 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4583,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.171880 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:16.310570 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.139s	user 0.090s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":936,"lbm_read_time_us":10251,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29194,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":49536,"update_count":2000}
I20260812 06:18:16.311342 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:16.361382 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.050s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14455,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.362102 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:16.379156 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.379812 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:16.545077 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.165s	user 0.092s	sys 0.073s 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":838,"lbm_read_time_us":13322,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28799,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:18:16.545727 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:16.593187 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.047s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18391,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.593714 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:16.604947 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.605563 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:16.736968 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.131s	user 0.114s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":676,"lbm_read_time_us":8466,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26301,"lbm_writes_lt_1ms":443,"mutex_wait_us":356,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2000}
I20260812 06:18:16.737512 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:16.777349 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.040s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16179,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.777964 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:16.793165 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.793740 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushMRSOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:16.825075 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushMRSOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":308,"dirs.run_wall_time_us":1465,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1700,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:16.826156 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling LogGCOp(8809c974149049d49247ca6b5727cf48): free 112239257 bytes of WAL
I20260812 06:18:16.826471 18808 log_reader.cc:385] T 8809c974149049d49247ca6b5727cf48: removed 11 log segments from log reader
I20260812 06:18:16.826527 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000003 (ops 12-16)
I20260812 06:18:16.826573 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000004 (ops 17-21)
I20260812 06:18:16.826609 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000005 (ops 22-26)
I20260812 06:18:16.826642 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000006 (ops 27-30)
I20260812 06:18:16.826663 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000007 (ops 31-35)
I20260812 06:18:16.826690 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000008 (ops 36-40)
I20260812 06:18:16.826719 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000009 (ops 41-45)
I20260812 06:18:16.826754 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000010 (ops 46-50)
I20260812 06:18:16.826789 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000011 (ops 51-55)
I20260812 06:18:16.826822 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000012 (ops 56-60)
I20260812 06:18:16.826849 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000013 (ops 61-65)
I20260812 06:18:16.853281 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: LogGCOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.027s	user 0.005s	sys 0.019s Metrics: {}
I20260812 06:18:16.853904 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=3.181125
I20260812 06:18:16.867270 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4605,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:16.867720 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling UndoDeltaBlockGCOp(8809c974149049d49247ca6b5727cf48): 463 bytes on disk
I20260812 06:18:16.868136 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: UndoDeltaBlockGCOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:16.868643 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:16.878509 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3573,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:16.879073 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:17.054672 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.175s	user 0.113s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":847,"lbm_read_time_us":11790,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34810,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:18:17.055421 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=14.095187
I20260812 06:18:17.107312 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.052s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19065,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.107914 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:17.119809 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.120527 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:17.289770 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.169s	user 0.110s	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":1116,"lbm_read_time_us":11104,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30727,"lbm_writes_lt_1ms":543,"mutex_wait_us":109,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:17.293908 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=14.095187
I20260812 06:18:17.354475 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.060s	user 0.038s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20631,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.354980 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:17.365908 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.366634 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:17.563460 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.197s	user 0.119s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":782,"lbm_read_time_us":13162,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35797,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22528,"update_count":2500}
I20260812 06:18:17.564247 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=14.095187
I20260812 06:18:17.608644 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.044s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20026,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.609272 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:17.760039 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.151s	user 0.102s	sys 0.047s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":887,"lbm_read_time_us":9594,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25787,"lbm_writes_lt_1ms":443,"mutex_wait_us":371,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:18:17.760922 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=11.118625
I20260812 06:18:17.802649 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.041s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":18245,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:17.803653 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:17.816993 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5345,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":450}
I20260812 06:18:17.817505 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:17.947778 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.130s	user 0.081s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":8180,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24289,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":34304,"update_count":2000}
I20260812 06:18:17.948467 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=11.118625
I20260812 06:18:17.985711 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.037s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16158,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:17.986276 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:17.999722 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5238,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.000171 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:18.120016 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.120s	user 0.107s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1972,"lbm_read_time_us":10103,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22963,"lbm_writes_lt_1ms":443,"mutex_wait_us":662,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:18.120838 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:18.158354 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.037s	user 0.033s	sys 0.000s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15503,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.158918 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:18.172196 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.172928 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushMRSOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:18.203500 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushMRSOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.030s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1346,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1712,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:18.204264 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling LogGCOp(8809c974149049d49247ca6b5727cf48): free 120553382 bytes of WAL
I20260812 06:18:18.204523 18808 log_reader.cc:385] T 8809c974149049d49247ca6b5727cf48: removed 12 log segments from log reader
I20260812 06:18:18.204571 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000014 (ops 66-70)
I20260812 06:18:18.204602 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000015 (ops 71-75)
I20260812 06:18:18.204659 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000016 (ops 76-80)
I20260812 06:18:18.204704 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000017 (ops 81-84)
I20260812 06:18:18.204723 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000018 (ops 85-89)
I20260812 06:18:18.204741 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000019 (ops 90-94)
I20260812 06:18:18.204794 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000020 (ops 95-99)
I20260812 06:18:18.204838 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000021 (ops 100-104)
I20260812 06:18:18.204877 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000022 (ops 105-109)
I20260812 06:18:18.204942 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000023 (ops 110-114)
I20260812 06:18:18.204979 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000024 (ops 115-118)
I20260812 06:18:18.205021 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000025 (ops 119-123)
I20260812 06:18:18.233482 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: LogGCOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:18.233927 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=6.157687
I20260812 06:18:18.262548 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.028s	user 0.017s	sys 0.011s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12200,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:18.263336 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling LogGCOp(8809c974149049d49247ca6b5727cf48): free 12017983 bytes of WAL
I20260812 06:18:18.263597 18808 log_reader.cc:385] T 8809c974149049d49247ca6b5727cf48: removed 1 log segments from log reader
I20260812 06:18:18.263661 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000026 (ops 124-128)
I20260812 06:18:18.266749 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: LogGCOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:18.267159 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:18.439116 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.172s	user 0.116s	sys 0.053s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":8275,"dirs.run_cpu_time_us":636,"dirs.run_wall_time_us":2761,"lbm_read_time_us":12652,"lbm_reads_lt_1ms":665,"lbm_write_time_us":35831,"lbm_writes_lt_1ms":643,"mutex_wait_us":2887,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:18:18.439744 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling UndoDeltaBlockGCOp(8809c974149049d49247ca6b5727cf48): 462 bytes on disk
I20260812 06:18:18.440140 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: UndoDeltaBlockGCOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.440881 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=14.095187
I20260812 06:18:18.492508 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.051s	user 0.018s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24601,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.493135 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:18.509630 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.510133 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:18.668841 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.159s	user 0.095s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1228,"lbm_read_time_us":9443,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32334,"lbm_writes_lt_1ms":543,"mutex_wait_us":305,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:18:18.669406 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=14.095187
I20260812 06:18:18.718626 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.049s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22026,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.719197 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:18.866180 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.147s	user 0.089s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":178,"lbm_read_time_us":10561,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24723,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.867221 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=11.118625
I20260812 06:18:18.913997 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.047s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":20743,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:18.914575 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:18.935868 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.021s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5187,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.936342 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:18.946935 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.947415 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:19.121155 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.174s	user 0.127s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":285,"lbm_read_time_us":11797,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29798,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":42240,"update_count":2500}
I20260812 06:18:19.122139 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=11.118625
I20260812 06:18:19.161089 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.039s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16561,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:19.161656 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:19.186658 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4975,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.187183 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:19.197614 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3960,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.198114 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:19.368296 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.170s	user 0.128s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":739,"lbm_read_time_us":10030,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34750,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:18:19.369160 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:19.414013 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.045s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19039,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.414695 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:19.432647 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.018s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5231,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.433161 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:19.559623 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.126s	user 0.106s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1361,"lbm_read_time_us":9206,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24859,"lbm_writes_lt_1ms":443,"mutex_wait_us":393,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:18:19.560267 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:19.609076 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.049s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15780,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.609634 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:19.625480 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.626101 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushMRSOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:19.659299 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushMRSOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.033s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1219,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2121,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:19.659994 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling LogGCOp(8809c974149049d49247ca6b5727cf48): free 112692608 bytes of WAL
I20260812 06:18:19.660228 18808 log_reader.cc:385] T 8809c974149049d49247ca6b5727cf48: removed 11 log segments from log reader
I20260812 06:18:19.660271 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000027 (ops 129-133)
I20260812 06:18:19.660306 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000028 (ops 134-138)
I20260812 06:18:19.660367 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000029 (ops 139-143)
I20260812 06:18:19.660413 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000030 (ops 144-148)
I20260812 06:18:19.660454 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000031 (ops 149-153)
I20260812 06:18:19.660494 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000032 (ops 154-158)
I20260812 06:18:19.660535 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000033 (ops 159-163)
I20260812 06:18:19.660576 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000034 (ops 164-168)
I20260812 06:18:19.660615 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000035 (ops 169-173)
I20260812 06:18:19.660655 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000036 (ops 174-178)
I20260812 06:18:19.660694 18808 log.cc:1079] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/8809c974149049d49247ca6b5727cf48/wal-000000037 (ops 179-183)
I20260812 06:18:19.686328 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: LogGCOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:19.686975 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling UndoDeltaBlockGCOp(8809c974149049d49247ca6b5727cf48): 447 bytes on disk
I20260812 06:18:19.687580 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: UndoDeltaBlockGCOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:19.688241 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:19.702637 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.703076 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:19.713850 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.714320 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:19.887110 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.173s	user 0.136s	sys 0.037s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":697,"lbm_read_time_us":15238,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34050,"lbm_writes_lt_1ms":643,"mutex_wait_us":38,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:19.890193 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=14.095187
I20260812 06:18:19.944657 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.054s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24897,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.945127 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=2.188937
I20260812 06:18:19.957118 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.957723 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:20.077502 18627 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.895s	user 1.894s	sys 0.127s
I20260812 06:18:20.110474 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.153s	user 0.129s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11274,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29522,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:20.111159 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48): perf score=10.126437
I20260812 06:18:20.153388 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: FlushDeltaMemStoresOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.042s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18613,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.154028 18907 maintenance_manager.cc:419] P 4d69ae9b62ec437180f325c69bb92948: Scheduling MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48): perf score=1.000000
I20260812 06:18:20.193495 18627 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.115s	user 0.002s	sys 0.000s
I20260812 06:18:20.194248 18627 tablet_server.cc:179] TabletServer@127.18.48.193:0 shutting down...
I20260812 06:18:20.264711 18808 maintenance_manager.cc:643] P 4d69ae9b62ec437180f325c69bb92948: MajorDeltaCompactionOp(8809c974149049d49247ca6b5727cf48) complete. Timing: real 0.110s	user 0.066s	sys 0.044s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1648,"lbm_read_time_us":10194,"lbm_reads_lt_1ms":367,"lbm_write_time_us":21333,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":461,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":1500}
I20260812 06:18:20.265444 18627 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:20.265892 18627 tablet_replica.cc:333] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948: stopping tablet replica
I20260812 06:18:20.266149 18627 raft_consensus.cc:2243] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:20.266450 18627 raft_consensus.cc:2272] T 8809c974149049d49247ca6b5727cf48 P 4d69ae9b62ec437180f325c69bb92948 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:20.281992 18627 tablet_server.cc:196] TabletServer@127.18.48.193:0 shutdown complete.
I20260812 06:18:20.297053 18627 master.cc:562] Master@127.18.48.254:43875 shutting down...
I20260812 06:18:20.300603 18627 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:20.300809 18627 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:20.300915 18627 tablet_replica.cc:333] T 00000000000000000000000000000000 P 38880994ee884debb5ee482087c8f266: stopping tablet replica
I20260812 06:18:20.313365 18627 master.cc:584] Master@127.18.48.254:43875 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5504 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:20.407188 18627 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.48.254:34085
I20260812 06:18:20.407610 18627 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:20.409690 18959 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:20.409693 18955 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:20.409878 18627 server_base.cc:1061] running on GCE node
W20260812 06:18:20.409710 18961 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:20.410161 18627 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:20.410209 18627 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:20.410225 18627 hybrid_clock.cc:648] HybridClock initialized: now 1786515500410225 us; error 0 us; skew 500 ppm
I20260812 06:18:20.411101 18627 webserver.cc:533] Webserver started at http://127.18.48.254:45497/ using document root <none> and password file <none>
I20260812 06:18:20.411237 18627 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:20.411279 18627 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:20.411371 18627 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:20.411790 18627 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/master-0-root/instance:
uuid: "5914dace4f2b4d11aac4e866213bfc25"
format_stamp: "Formatted at 2026-08-12 06:18:20 on dist-test-slave-tk9z"
I20260812 06:18:20.413235 18627 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:20.414129 18970 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:20.414361 18627 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:20.414479 18627 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/master-0-root
uuid: "5914dace4f2b4d11aac4e866213bfc25"
format_stamp: "Formatted at 2026-08-12 06:18:20 on dist-test-slave-tk9z"
I20260812 06:18:20.414577 18627 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:20.423341 18627 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:20.423821 18627 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:20.428709 18627 rpc_server.cc:307] RPC server started. Bound to: 127.18.48.254:34085
I20260812 06:18:20.432122 19060 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.48.254:34085 every 8 connection(s)
I20260812 06:18:20.437163 19061 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:20.446971 19061 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25: Bootstrap starting.
I20260812 06:18:20.447813 19061 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:20.448910 19061 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25: No bootstrap required, opened a new log
I20260812 06:18:20.449290 19061 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5914dace4f2b4d11aac4e866213bfc25" member_type: VOTER }
I20260812 06:18:20.449383 19061 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:20.449407 19061 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5914dace4f2b4d11aac4e866213bfc25, State: Initialized, Role: FOLLOWER
I20260812 06:18:20.449558 19061 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [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: "5914dace4f2b4d11aac4e866213bfc25" member_type: VOTER }
I20260812 06:18:20.449623 19061 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:20.449648 19061 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:20.449685 19061 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:20.450454 19061 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5914dace4f2b4d11aac4e866213bfc25" member_type: VOTER }
I20260812 06:18:20.450577 19061 leader_election.cc:304] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [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: 5914dace4f2b4d11aac4e866213bfc25; no voters: 
I20260812 06:18:20.450739 19061 leader_election.cc:290] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:20.450963 19066 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:20.451201 19066 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 1 LEADER]: Becoming Leader. State: Replica: 5914dace4f2b4d11aac4e866213bfc25, State: Running, Role: LEADER
I20260812 06:18:20.451326 19061 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:20.451371 19066 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [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: "5914dace4f2b4d11aac4e866213bfc25" member_type: VOTER }
I20260812 06:18:20.451879 19067 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5914dace4f2b4d11aac4e866213bfc25" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5914dace4f2b4d11aac4e866213bfc25" member_type: VOTER } }
I20260812 06:18:20.451936 19069 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5914dace4f2b4d11aac4e866213bfc25. Latest consensus state: current_term: 1 leader_uuid: "5914dace4f2b4d11aac4e866213bfc25" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5914dace4f2b4d11aac4e866213bfc25" member_type: VOTER } }
I20260812 06:18:20.452018 19067 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:20.452030 19069 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:20.452333 19075 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:20.453276 19075 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:20.453477 18627 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:20.455385 19075 catalog_manager.cc:1383] Generated new cluster ID: c9ec389a48f649e3bb37532d720c2df2
I20260812 06:18:20.455451 19075 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:20.470677 19075 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:20.471342 19075 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:20.478832 19075 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25: Generated new TSK 0
I20260812 06:18:20.479044 19075 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:20.485935 18627 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:20.488130 19097 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:20.488189 19100 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:20.488197 18627 server_base.cc:1061] running on GCE node
W20260812 06:18:20.488130 19095 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:20.488634 18627 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:20.488679 18627 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:20.488695 18627 hybrid_clock.cc:648] HybridClock initialized: now 1786515500488695 us; error 0 us; skew 500 ppm
I20260812 06:18:20.489522 18627 webserver.cc:533] Webserver started at http://127.18.48.193:40455/ using document root <none> and password file <none>
I20260812 06:18:20.489658 18627 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:20.489710 18627 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:20.489768 18627 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:20.490134 18627 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/instance:
uuid: "d5c2fd30ae104508b81ecf2517c5d251"
format_stamp: "Formatted at 2026-08-12 06:18:20 on dist-test-slave-tk9z"
I20260812 06:18:20.491734 18627 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:20.492697 19106 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:20.492960 18627 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:20.493052 18627 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root
uuid: "d5c2fd30ae104508b81ecf2517c5d251"
format_stamp: "Formatted at 2026-08-12 06:18:20 on dist-test-slave-tk9z"
I20260812 06:18:20.493140 18627 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:20.506304 18627 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:20.506760 18627 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:20.507094 18627 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:20.507577 18627 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:20.507644 18627 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:20.507704 18627 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:20.507753 18627 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:20.511910 18627 rpc_server.cc:307] RPC server started. Bound to: 127.18.48.193:34967
I20260812 06:18:20.511953 19227 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.48.193:34967 every 8 connection(s)
I20260812 06:18:20.520074 19229 heartbeater.cc:344] Connected to a master server at 127.18.48.254:34085
I20260812 06:18:20.520190 19229 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:20.520468 19229 heartbeater.cc:507] Master 127.18.48.254:34085 requested a full tablet report, sending...
I20260812 06:18:20.521145 19001 ts_manager.cc:194] Registered new tserver with Master: d5c2fd30ae104508b81ecf2517c5d251 (127.18.48.193:34967)
I20260812 06:18:20.521242 18627 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008899087s
I20260812 06:18:20.522167 19001 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51386
I20260812 06:18:20.528721 19001 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51396:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:20.537706 19169 tablet_service.cc:1511] Processing CreateTablet for tablet 4156ce5e1921492182d5887e8b997c87 (DEFAULT_TABLE table=heavy-update-compaction-test [id=75316614b7ec408abdd9c3b764e1fb55]), partition=
I20260812 06:18:20.537999 19169 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4156ce5e1921492182d5887e8b997c87. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:20.539928 19247 tablet_bootstrap.cc:492] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Bootstrap starting.
I20260812 06:18:20.540899 19247 tablet_bootstrap.cc:654] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:20.541988 19247 tablet_bootstrap.cc:492] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: No bootstrap required, opened a new log
I20260812 06:18:20.542104 19247 ts_tablet_manager.cc:1403] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:20.542600 19247 raft_consensus.cc:359] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d5c2fd30ae104508b81ecf2517c5d251" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 34967 } }
I20260812 06:18:20.542712 19247 raft_consensus.cc:385] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:20.542759 19247 raft_consensus.cc:740] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d5c2fd30ae104508b81ecf2517c5d251, State: Initialized, Role: FOLLOWER
I20260812 06:18:20.542898 19247 consensus_queue.cc:260] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [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: "d5c2fd30ae104508b81ecf2517c5d251" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 34967 } }
I20260812 06:18:20.543010 19247 raft_consensus.cc:399] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:20.543058 19247 raft_consensus.cc:493] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:20.543118 19247 raft_consensus.cc:3060] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:20.544003 19247 raft_consensus.cc:515] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d5c2fd30ae104508b81ecf2517c5d251" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 34967 } }
I20260812 06:18:20.544122 19247 leader_election.cc:304] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [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: d5c2fd30ae104508b81ecf2517c5d251; no voters: 
I20260812 06:18:20.544281 19247 leader_election.cc:290] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:20.544411 19253 raft_consensus.cc:2804] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:20.544641 19229 heartbeater.cc:499] Master 127.18.48.254:34085 was elected leader, sending a full tablet report...
I20260812 06:18:20.544639 19253 raft_consensus.cc:697] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 1 LEADER]: Becoming Leader. State: Replica: d5c2fd30ae104508b81ecf2517c5d251, State: Running, Role: LEADER
I20260812 06:18:20.544662 19247 ts_tablet_manager.cc:1434] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:20.544816 19253 consensus_queue.cc:237] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [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: "d5c2fd30ae104508b81ecf2517c5d251" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 34967 } }
I20260812 06:18:20.546067 19001 catalog_manager.cc:5719] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 reported cstate change: term changed from 0 to 1, leader changed from <none> to d5c2fd30ae104508b81ecf2517c5d251 (127.18.48.193). New cstate: current_term: 1 leader_uuid: "d5c2fd30ae104508b81ecf2517c5d251" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d5c2fd30ae104508b81ecf2517c5d251" member_type: VOTER last_known_addr { host: "127.18.48.193" port: 34967 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:20.608073 18627 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.018s	sys 0.005s
I20260812 06:18:20.762785 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushMRSOp(4156ce5e1921492182d5887e8b997c87): perf score=19.054940
I20260812 06:18:20.920655 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushMRSOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.158s	user 0.104s	sys 0.052s Metrics: {"bytes_written":12676713,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":842,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39926,"lbm_writes_lt_1ms":766,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":4352,"update_count":1545}
I20260812 06:18:20.922240 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling LogGCOp(4156ce5e1921492182d5887e8b997c87): free 20743880 bytes of WAL
I20260812 06:18:20.922611 19117 log_reader.cc:385] T 4156ce5e1921492182d5887e8b997c87: removed 2 log segments from log reader
I20260812 06:18:20.922710 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000001 (ops 1-6)
I20260812 06:18:20.922814 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000002 (ops 7-11)
I20260812 06:18:20.928898 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: LogGCOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.006s	user 0.004s	sys 0.000s Metrics: {}
I20260812 06:18:20.929483 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:20.952551 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.023s	user 0.010s	sys 0.002s Metrics: {"bytes_written":3815488,"delete_count":0,"lbm_write_time_us":4689,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:20.953052 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling UndoDeltaBlockGCOp(4156ce5e1921492182d5887e8b997c87): 16411392 bytes on disk
I20260812 06:18:20.953475 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: UndoDeltaBlockGCOp(4156ce5e1921492182d5887e8b997c87) 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:18:20.953933 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:20.964040 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":3768,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:18:20.964486 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:21.123728 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.159s	user 0.112s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774810,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1027,"lbm_read_time_us":10979,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27717,"lbm_writes_lt_1ms":543,"mutex_wait_us":160,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24704,"thread_start_us":332,"threads_started":5,"update_count":2500}
I20260812 06:18:21.124329 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:21.177095 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.053s	user 0.013s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20418,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.177547 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:21.188661 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.189422 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:21.337800 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.148s	user 0.118s	sys 0.024s 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":357,"lbm_read_time_us":10239,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29017,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:18:21.338539 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:21.388121 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.049s	user 0.023s	sys 0.021s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":20381,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.388628 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:21.400216 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.400961 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:21.563408 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.162s	user 0.091s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":149,"lbm_read_time_us":10239,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28614,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":172800,"update_count":2500}
I20260812 06:18:21.564240 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:21.616796 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.052s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24261,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.617291 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:21.773465 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.156s	user 0.108s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":199,"lbm_read_time_us":10048,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24347,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:18:21.774247 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:21.825547 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.051s	user 0.029s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22956,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.826153 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:21.841751 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5992,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.842322 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:22.055289 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.210s	user 0.150s	sys 0.047s 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":202,"lbm_read_time_us":12389,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33194,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:18:22.056078 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:22.115526 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.059s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25208,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.116164 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:22.127938 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.128420 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushMRSOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:22.159140 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushMRSOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.031s	user 0.025s	sys 0.005s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1372,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2114,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:22.159706 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling LogGCOp(4156ce5e1921492182d5887e8b997c87): free 112239265 bytes of WAL
I20260812 06:18:22.159929 19117 log_reader.cc:385] T 4156ce5e1921492182d5887e8b997c87: removed 11 log segments from log reader
I20260812 06:18:22.159988 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000003 (ops 12-16)
I20260812 06:18:22.160041 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000004 (ops 17-21)
I20260812 06:18:22.160099 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000005 (ops 22-26)
I20260812 06:18:22.160140 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000006 (ops 27-31)
I20260812 06:18:22.160192 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000007 (ops 32-36)
I20260812 06:18:22.160233 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000008 (ops 37-41)
I20260812 06:18:22.160269 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000009 (ops 42-46)
I20260812 06:18:22.160305 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000010 (ops 47-51)
I20260812 06:18:22.160351 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000011 (ops 52-56)
I20260812 06:18:22.160385 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000012 (ops 57-60)
I20260812 06:18:22.160422 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000013 (ops 61-65)
I20260812 06:18:22.183544 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: LogGCOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:22.190188 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling UndoDeltaBlockGCOp(4156ce5e1921492182d5887e8b997c87): 463 bytes on disk
I20260812 06:18:22.190768 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: UndoDeltaBlockGCOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:22.191323 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:22.208619 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.017s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.209051 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling LogGCOp(4156ce5e1921492182d5887e8b997c87): free 12017983 bytes of WAL
I20260812 06:18:22.209245 19117 log_reader.cc:385] T 4156ce5e1921492182d5887e8b997c87: removed 1 log segments from log reader
I20260812 06:18:22.209303 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000014 (ops 66-70)
I20260812 06:18:22.211761 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: LogGCOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:22.212039 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:22.222777 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.223479 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:22.469393 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.246s	user 0.139s	sys 0.101s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1024,"lbm_read_time_us":17836,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38185,"lbm_writes_lt_1ms":743,"mutex_wait_us":83,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":24576,"thread_start_us":114,"threads_started":1,"update_count":3500}
I20260812 06:18:22.470119 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=18.063937
I20260812 06:18:22.545749 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.075s	user 0.030s	sys 0.033s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":31323,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:22.546192 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:22.558318 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.558912 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:22.766690 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.208s	user 0.143s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1130,"lbm_read_time_us":14158,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35062,"lbm_writes_lt_1ms":643,"mutex_wait_us":305,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":3000}
I20260812 06:18:22.767453 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:22.819406 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.052s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21136,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.820140 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:22.976938 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.157s	user 0.100s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":221,"lbm_read_time_us":10605,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25929,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:18:22.977557 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:23.024945 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.047s	user 0.035s	sys 0.009s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20511,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.025616 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:23.037139 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4178,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.037643 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:23.213297 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.175s	user 0.107s	sys 0.062s 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":561,"lbm_read_time_us":10060,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27000,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:18:23.214121 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=11.118625
I20260812 06:18:23.244617 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.030s	user 0.018s	sys 0.010s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13124,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:23.245584 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:23.260888 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.015s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5007,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.261418 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:23.388152 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.127s	user 0.102s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":519,"lbm_read_time_us":7906,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27046,"lbm_writes_lt_1ms":443,"mutex_wait_us":348,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:18:23.388993 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=10.126437
I20260812 06:18:23.434799 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.044s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19841,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.435277 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:23.449985 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.015s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.450544 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:23.582468 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.132s	user 0.101s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":359,"lbm_read_time_us":7419,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25654,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.583338 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=11.118625
I20260812 06:18:23.625278 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.042s	user 0.033s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18316,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:23.625892 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:23.639758 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4973,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.640422 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushMRSOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:23.672557 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushMRSOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1306,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1538,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:23.673233 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling LogGCOp(4156ce5e1921492182d5887e8b997c87): free 108988505 bytes of WAL
I20260812 06:18:23.673506 19117 log_reader.cc:385] T 4156ce5e1921492182d5887e8b997c87: removed 11 log segments from log reader
I20260812 06:18:23.673571 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000015 (ops 71-75)
I20260812 06:18:23.673624 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000016 (ops 76-80)
I20260812 06:18:23.673661 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000017 (ops 81-85)
I20260812 06:18:23.673700 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000018 (ops 86-90)
I20260812 06:18:23.673738 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000019 (ops 91-95)
I20260812 06:18:23.673774 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000020 (ops 96-100)
I20260812 06:18:23.673811 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000021 (ops 101-104)
I20260812 06:18:23.673848 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000022 (ops 105-109)
I20260812 06:18:23.673887 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000023 (ops 110-114)
I20260812 06:18:23.673923 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000024 (ops 115-119)
I20260812 06:18:23.673967 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000025 (ops 120-124)
I20260812 06:18:23.699524 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: LogGCOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:23.699978 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling UndoDeltaBlockGCOp(4156ce5e1921492182d5887e8b997c87): 462 bytes on disk
I20260812 06:18:23.700387 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: UndoDeltaBlockGCOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:23.700917 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=3.181125
I20260812 06:18:23.714489 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4882125,"delete_count":0,"lbm_write_time_us":5154,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:18:23.714998 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling LogGCOp(4156ce5e1921492182d5887e8b997c87): free 11564877 bytes of WAL
I20260812 06:18:23.715241 19117 log_reader.cc:385] T 4156ce5e1921492182d5887e8b997c87: removed 1 log segments from log reader
I20260812 06:18:23.715303 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000026 (ops 125-128)
I20260812 06:18:23.718281 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: LogGCOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:23.718649 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:23.729918 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":3549,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:18:23.730584 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:23.904740 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.174s	user 0.129s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877317,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":948,"lbm_read_time_us":13653,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33552,"lbm_writes_lt_1ms":643,"mutex_wait_us":100,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:23.905553 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:23.960713 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.055s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24428,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.961242 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:23.972435 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4233,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.973114 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:24.152010 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.179s	user 0.122s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":433,"lbm_read_time_us":11308,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35476,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:18:24.152879 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=12.110812
I20260812 06:18:24.192785 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.040s	user 0.021s	sys 0.015s Metrics: {"bytes_written":13579241,"delete_count":0,"lbm_write_time_us":16759,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1655}
I20260812 06:18:24.193471 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=1.196750
I20260812 06:18:24.206321 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":4665,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:18:24.206856 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:24.378137 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.171s	user 0.146s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":246,"lbm_read_time_us":10188,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29150,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21760,"update_count":2000}
I20260812 06:18:24.378938 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:24.433357 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.054s	user 0.023s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20926,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.433907 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:24.463959 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.030s	user 0.009s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.464697 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:24.681607 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.217s	user 0.155s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":491,"lbm_read_time_us":15563,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32357,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:18:24.682226 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:24.737730 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.055s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24284,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.738377 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:24.750675 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.012s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4632,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.751277 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:24.954641 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.203s	user 0.145s	sys 0.045s 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":942,"lbm_read_time_us":12092,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32023,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:24.955369 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:25.009652 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.054s	user 0.038s	sys 0.013s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":26064,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.010214 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:25.022526 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.023074 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:25.199229 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.176s	user 0.141s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":10352,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33046,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":2500}
I20260812 06:18:25.200101 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=14.095187
I20260812 06:18:25.260120 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.060s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25195,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.260634 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:25.272133 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3953,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.272730 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushMRSOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:25.303534 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushMRSOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":392,"dirs.run_wall_time_us":1841,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2035,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:25.304351 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling LogGCOp(4156ce5e1921492182d5887e8b997c87): free 124710578 bytes of WAL
I20260812 06:18:25.304632 19117 log_reader.cc:385] T 4156ce5e1921492182d5887e8b997c87: removed 12 log segments from log reader
I20260812 06:18:25.304697 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000027 (ops 129-133)
I20260812 06:18:25.304733 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000028 (ops 134-138)
I20260812 06:18:25.304755 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000029 (ops 139-143)
I20260812 06:18:25.304781 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000030 (ops 144-148)
I20260812 06:18:25.304816 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000031 (ops 149-153)
I20260812 06:18:25.304849 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000032 (ops 154-158)
I20260812 06:18:25.304883 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000033 (ops 159-163)
I20260812 06:18:25.304912 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000034 (ops 164-168)
I20260812 06:18:25.304934 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000035 (ops 169-173)
I20260812 06:18:25.304965 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000036 (ops 174-178)
I20260812 06:18:25.304999 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000037 (ops 179-183)
I20260812 06:18:25.305029 19117 log.cc:1079] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: Deleting log segment in path: /tmp/dist-test-taskqa62ok/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494891923-18627-0/minicluster-data/ts-0-root/wals/4156ce5e1921492182d5887e8b997c87/wal-000000038 (ops 184-188)
I20260812 06:18:25.334807 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: LogGCOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:25.335214 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:25.356686 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.021s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6485,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.357195 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling UndoDeltaBlockGCOp(4156ce5e1921492182d5887e8b997c87): 483 bytes on disk
I20260812 06:18:25.357600 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: UndoDeltaBlockGCOp(4156ce5e1921492182d5887e8b997c87) 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:18:25.358130 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=2.188937
I20260812 06:18:25.380443 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.022s	user 0.006s	sys 0.014s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4132,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.380973 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87): perf score=1.000000
I20260812 06:18:25.613950 18627 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.006s	user 1.860s	sys 0.168s
I20260812 06:18:25.617287 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: MajorDeltaCompactionOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.236s	user 0.154s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1290,"lbm_read_time_us":14770,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39836,"lbm_writes_lt_1ms":743,"mutex_wait_us":382,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:18:25.617934 19230 maintenance_manager.cc:419] P d5c2fd30ae104508b81ecf2517c5d251: Scheduling FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87): perf score=18.063937
I20260812 06:18:25.643250 18627 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.029s	user 0.000s	sys 0.002s
I20260812 06:18:25.643873 18627 tablet_server.cc:179] TabletServer@127.18.48.193:0 shutting down...
I20260812 06:18:25.682328 19117 maintenance_manager.cc:643] P d5c2fd30ae104508b81ecf2517c5d251: FlushDeltaMemStoresOp(4156ce5e1921492182d5887e8b997c87) complete. Timing: real 0.064s	user 0.043s	sys 0.018s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24010,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:25.683121 18627 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:25.683377 18627 tablet_replica.cc:333] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251: stopping tablet replica
I20260812 06:18:25.683542 18627 raft_consensus.cc:2243] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:25.683733 18627 raft_consensus.cc:2272] T 4156ce5e1921492182d5887e8b997c87 P d5c2fd30ae104508b81ecf2517c5d251 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:25.687011 18627 tablet_server.cc:196] TabletServer@127.18.48.193:0 shutdown complete.
I20260812 06:18:25.689724 18627 master.cc:562] Master@127.18.48.254:34085 shutting down...
I20260812 06:18:25.693737 18627 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:25.693935 18627 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:25.694021 18627 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5914dace4f2b4d11aac4e866213bfc25: stopping tablet replica
I20260812 06:18:25.706449 18627 master.cc:584] Master@127.18.48.254:34085 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5391 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10896 ms total)

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