[==========] 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:56.626729  6942 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.199.190:40359
I20260812 06:18:56.627794  6942 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:56.628432  6942 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:56.635473  6955 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:56.635617  6951 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:56.635703  6942 server_base.cc:1061] running on GCE node
W20260812 06:18:56.635928  6953 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:56.636492  6942 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:56.636622  6942 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:56.636688  6942 hybrid_clock.cc:648] HybridClock initialized: now 1786515536636685 us; error 0 us; skew 500 ppm
I20260812 06:18:56.638613  6942 webserver.cc:533] Webserver started at http://127.6.199.190:38505/ using document root <none> and password file <none>
I20260812 06:18:56.639196  6942 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:56.639304  6942 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:56.639571  6942 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:56.641346  6942 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/master-0-root/instance:
uuid: "bb7c47bb94384a8e87285c390392cc00"
format_stamp: "Formatted at 2026-08-12 06:18:56 on dist-test-slave-s11t"
I20260812 06:18:56.645087  6942 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:56.647449  6966 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:56.648608  6942 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:56.648808  6942 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/master-0-root
uuid: "bb7c47bb94384a8e87285c390392cc00"
format_stamp: "Formatted at 2026-08-12 06:18:56 on dist-test-slave-s11t"
I20260812 06:18:56.648936  6942 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-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:56.670871  6942 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:56.671598  6942 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:56.671818  6942 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:56.680371  6942 rpc_server.cc:307] RPC server started. Bound to: 127.6.199.190:40359
I20260812 06:18:56.680384  7054 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.199.190:40359 every 8 connection(s)
I20260812 06:18:56.682952  7055 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:56.688946  7055 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00: Bootstrap starting.
I20260812 06:18:56.691362  7055 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:56.692306  7055 log.cc:826] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:56.694264  7055 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00: No bootstrap required, opened a new log
I20260812 06:18:56.697247  7055 raft_consensus.cc:359] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb7c47bb94384a8e87285c390392cc00" member_type: VOTER }
I20260812 06:18:56.697558  7055 raft_consensus.cc:385] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:56.697644  7055 raft_consensus.cc:740] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bb7c47bb94384a8e87285c390392cc00, State: Initialized, Role: FOLLOWER
I20260812 06:18:56.698312  7055 consensus_queue.cc:260] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [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: "bb7c47bb94384a8e87285c390392cc00" member_type: VOTER }
I20260812 06:18:56.698472  7055 raft_consensus.cc:399] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:56.698518  7055 raft_consensus.cc:493] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:56.698640  7055 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:56.699465  7055 raft_consensus.cc:515] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb7c47bb94384a8e87285c390392cc00" member_type: VOTER }
I20260812 06:18:56.699879  7055 leader_election.cc:304] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [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: bb7c47bb94384a8e87285c390392cc00; no voters: 
I20260812 06:18:56.700188  7055 leader_election.cc:290] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:56.700377  7061 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:56.700645  7061 raft_consensus.cc:697] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 1 LEADER]: Becoming Leader. State: Replica: bb7c47bb94384a8e87285c390392cc00, State: Running, Role: LEADER
I20260812 06:18:56.701141  7061 consensus_queue.cc:237] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [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: "bb7c47bb94384a8e87285c390392cc00" member_type: VOTER }
I20260812 06:18:56.701359  7055 sys_catalog.cc:565] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:56.703248  7064 sys_catalog.cc:455] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [sys.catalog]: SysCatalogTable state changed. Reason: New leader bb7c47bb94384a8e87285c390392cc00. Latest consensus state: current_term: 1 leader_uuid: "bb7c47bb94384a8e87285c390392cc00" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb7c47bb94384a8e87285c390392cc00" member_type: VOTER } }
I20260812 06:18:56.703271  7062 sys_catalog.cc:455] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bb7c47bb94384a8e87285c390392cc00" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb7c47bb94384a8e87285c390392cc00" member_type: VOTER } }
I20260812 06:18:56.703429  7062 sys_catalog.cc:458] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:56.703429  7064 sys_catalog.cc:458] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:56.703770  6942 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:56.703989  7085 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:56.706482  7085 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:56.711882  7085 catalog_manager.cc:1383] Generated new cluster ID: 6ad1978a21774486b9a764b3c8ec7790
I20260812 06:18:56.711993  7085 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:56.743781  7085 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:56.744856  7085 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:56.750051  7085 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00: Generated new TSK 0
I20260812 06:18:56.750716  7085 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:56.769240  6942 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:56.772173  7095 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:56.772315  6942 server_base.cc:1061] running on GCE node
W20260812 06:18:56.772138  7092 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:56.772150  7090 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:56.772660  6942 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:56.772740  6942 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:56.772763  6942 hybrid_clock.cc:648] HybridClock initialized: now 1786515536772763 us; error 0 us; skew 500 ppm
I20260812 06:18:56.773789  6942 webserver.cc:533] Webserver started at http://127.6.199.129:37409/ using document root <none> and password file <none>
I20260812 06:18:56.773967  6942 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:56.774029  6942 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:56.774107  6942 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:56.774542  6942 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/instance:
uuid: "df4a86ee0e60480f93249ca80438b95c"
format_stamp: "Formatted at 2026-08-12 06:18:56 on dist-test-slave-s11t"
I20260812 06:18:56.776446  6942 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:56.777614  7102 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:56.778028  6942 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:56.778126  6942 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root
uuid: "df4a86ee0e60480f93249ca80438b95c"
format_stamp: "Formatted at 2026-08-12 06:18:56 on dist-test-slave-s11t"
I20260812 06:18:56.778192  6942 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-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:56.789836  6942 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:56.790354  6942 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:56.790848  6942 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:56.791817  6942 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:56.791899  6942 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:56.791999  6942 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:56.792052  6942 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:56.799697  6942 rpc_server.cc:307] RPC server started. Bound to: 127.6.199.129:42041
I20260812 06:18:56.799736  7213 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.199.129:42041 every 8 connection(s)
I20260812 06:18:56.810930  7214 heartbeater.cc:344] Connected to a master server at 127.6.199.190:40359
I20260812 06:18:56.811244  7214 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:56.811751  7214 heartbeater.cc:507] Master 127.6.199.190:40359 requested a full tablet report, sending...
I20260812 06:18:56.813366  6998 ts_manager.cc:194] Registered new tserver with Master: df4a86ee0e60480f93249ca80438b95c (127.6.199.129:42041)
I20260812 06:18:56.813935  6942 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013538347s
I20260812 06:18:56.814998  6998 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44300
I20260812 06:18:56.824465  6998 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44312:
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:56.839260  7154 tablet_service.cc:1511] Processing CreateTablet for tablet 7c2c93e925594fe2bba17f52395e507b (DEFAULT_TABLE table=heavy-update-compaction-test [id=afb628a6f6264dc7af0570dd273761c3]), partition=
I20260812 06:18:56.839787  7154 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7c2c93e925594fe2bba17f52395e507b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:56.842303  7235 tablet_bootstrap.cc:492] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Bootstrap starting.
I20260812 06:18:56.844043  7235 tablet_bootstrap.cc:654] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:56.845429  7235 tablet_bootstrap.cc:492] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: No bootstrap required, opened a new log
I20260812 06:18:56.845536  7235 ts_tablet_manager.cc:1403] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:56.846062  7235 raft_consensus.cc:359] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df4a86ee0e60480f93249ca80438b95c" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 42041 } }
I20260812 06:18:56.846252  7235 raft_consensus.cc:385] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:56.846313  7235 raft_consensus.cc:740] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: df4a86ee0e60480f93249ca80438b95c, State: Initialized, Role: FOLLOWER
I20260812 06:18:56.846479  7235 consensus_queue.cc:260] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [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: "df4a86ee0e60480f93249ca80438b95c" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 42041 } }
I20260812 06:18:56.846593  7235 raft_consensus.cc:399] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:56.846673  7235 raft_consensus.cc:493] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:56.846740  7235 raft_consensus.cc:3060] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:56.847741  7235 raft_consensus.cc:515] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df4a86ee0e60480f93249ca80438b95c" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 42041 } }
I20260812 06:18:56.847893  7235 leader_election.cc:304] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [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: df4a86ee0e60480f93249ca80438b95c; no voters: 
I20260812 06:18:56.848133  7235 leader_election.cc:290] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:56.848259  7239 raft_consensus.cc:2804] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:56.848541  7239 raft_consensus.cc:697] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 1 LEADER]: Becoming Leader. State: Replica: df4a86ee0e60480f93249ca80438b95c, State: Running, Role: LEADER
I20260812 06:18:56.848740  7239 consensus_queue.cc:237] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [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: "df4a86ee0e60480f93249ca80438b95c" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 42041 } }
I20260812 06:18:56.848868  7214 heartbeater.cc:499] Master 127.6.199.190:40359 was elected leader, sending a full tablet report...
I20260812 06:18:56.848526  7235 ts_tablet_manager.cc:1434] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:56.851724  6998 catalog_manager.cc:5719] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c reported cstate change: term changed from 0 to 1, leader changed from <none> to df4a86ee0e60480f93249ca80438b95c (127.6.199.129). New cstate: current_term: 1 leader_uuid: "df4a86ee0e60480f93249ca80438b95c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df4a86ee0e60480f93249ca80438b95c" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 42041 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:56.920501  6942 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.015s	sys 0.012s
I20260812 06:18:57.051034  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushMRSOp(7c2c93e925594fe2bba17f52395e507b): perf score=15.086190
I20260812 06:18:57.222743  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushMRSOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.171s	user 0.124s	sys 0.036s Metrics: {"bytes_written":11897250,"cfile_init":1,"compiler_manager_pool.queue_time_us":244,"delete_count":0,"dirs.queue_time_us":158,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":920,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42812,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":99,"threads_started":1,"update_count":1450}
I20260812 06:18:57.223846  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling LogGCOp(7c2c93e925594fe2bba17f52395e507b): free 20743880 bytes of WAL
I20260812 06:18:57.224179  7110 log_reader.cc:385] T 7c2c93e925594fe2bba17f52395e507b: removed 2 log segments from log reader
I20260812 06:18:57.224260  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000001 (ops 1-6)
I20260812 06:18:57.224375  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000002 (ops 7-11)
I20260812 06:18:57.228854  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: LogGCOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:57.229226  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling UndoDeltaBlockGCOp(7c2c93e925594fe2bba17f52395e507b): 12719217 bytes on disk
I20260812 06:18:57.229818  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: UndoDeltaBlockGCOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:57.230216  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:57.247120  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.017s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6343,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.247601  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:57.397354  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.150s	user 0.118s	sys 0.032s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262037,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":936,"lbm_read_time_us":8116,"lbm_reads_lt_1ms":454,"lbm_write_time_us":27974,"lbm_writes_lt_1ms":433,"mutex_wait_us":3,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":335,"threads_started":5,"update_count":1950}
I20260812 06:18:57.397961  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=10.126437
I20260812 06:18:57.443019  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.045s	user 0.018s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14669,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.443506  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:57.454644  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.455288  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:57.588894  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.133s	user 0.099s	sys 0.032s 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":1132,"lbm_read_time_us":9787,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25409,"lbm_writes_lt_1ms":443,"mutex_wait_us":329,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:57.589648  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=10.126437
I20260812 06:18:57.627287  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.037s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":15152,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.627843  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:57.642987  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.643573  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:57.765398  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.122s	user 0.106s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672281,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1044,"lbm_read_time_us":9488,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22752,"lbm_writes_lt_1ms":443,"mutex_wait_us":256,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.766163  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=10.126437
I20260812 06:18:57.817327  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.051s	user 0.030s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20366,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.817921  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:57.835497  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.836094  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:57.980458  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.144s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":334,"lbm_read_time_us":11215,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23344,"lbm_writes_lt_1ms":443,"mutex_wait_us":140,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:18:57.981158  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=10.126437
I20260812 06:18:58.026952  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.046s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18789,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.027518  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:58.038512  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4159,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.039175  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:58.165930  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.127s	user 0.098s	sys 0.028s 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":455,"lbm_read_time_us":9229,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23400,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:18:58.166565  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=10.126437
I20260812 06:18:58.204340  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.038s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15931,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.204957  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:58.218247  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.218713  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:58.341885  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.123s	user 0.102s	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":105,"lbm_read_time_us":8591,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25816,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:58.342926  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=10.126437
I20260812 06:18:58.396450  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.052s	user 0.030s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20277,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.397051  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:58.408154  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.408617  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:58.567842  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.159s	user 0.098s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":11801,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24568,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39424,"update_count":2000}
I20260812 06:18:58.568316  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=10.126437
I20260812 06:18:58.620546  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.052s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20178,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.621220  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:58.637024  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.637794  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushMRSOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:58.675786  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushMRSOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.038s	user 0.032s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1559,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1874,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:58.677068  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling LogGCOp(7c2c93e925594fe2bba17f52395e507b): free 124257246 bytes of WAL
I20260812 06:18:58.677371  7110 log_reader.cc:385] T 7c2c93e925594fe2bba17f52395e507b: removed 12 log segments from log reader
I20260812 06:18:58.677430  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000003 (ops 12-16)
I20260812 06:18:58.677466  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000004 (ops 17-21)
I20260812 06:18:58.677489  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000005 (ops 22-26)
I20260812 06:18:58.677521  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000006 (ops 27-31)
I20260812 06:18:58.677553  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000007 (ops 32-36)
I20260812 06:18:58.677580  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000008 (ops 37-41)
I20260812 06:18:58.677608  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000009 (ops 42-46)
I20260812 06:18:58.677634  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000010 (ops 47-50)
I20260812 06:18:58.677656  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000011 (ops 51-55)
I20260812 06:18:58.677702  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000012 (ops 56-60)
I20260812 06:18:58.677736  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000013 (ops 61-65)
I20260812 06:18:58.677758  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000014 (ops 66-70)
I20260812 06:18:58.711067  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: LogGCOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.034s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:58.713233  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:58.747426  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.034s	user 0.013s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6246,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.748070  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:58.759068  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.759485  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:58.957777  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.198s	user 0.117s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3819,"lbm_read_time_us":14042,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32598,"lbm_writes_lt_1ms":643,"mutex_wait_us":1381,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":124,"threads_started":1,"update_count":3000}
I20260812 06:18:58.958693  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling UndoDeltaBlockGCOp(7c2c93e925594fe2bba17f52395e507b): 485 bytes on disk
I20260812 06:18:58.959157  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: UndoDeltaBlockGCOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.959653  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:18:59.020036  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.060s	user 0.021s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20010,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.020596  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:59.031508  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.031971  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:59.206969  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.175s	user 0.120s	sys 0.048s 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":190,"lbm_read_time_us":13209,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30022,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:18:59.207676  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=11.118625
I20260812 06:18:59.243525  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.036s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15561,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:59.244078  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:59.260375  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5901,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.260901  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:59.404048  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.143s	user 0.095s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":7640,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25408,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2000}
I20260812 06:18:59.404598  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:18:59.461514  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.057s	user 0.024s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22551,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.462028  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:59.472997  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.473737  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:59.629915  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.156s	user 0.104s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":737,"lbm_read_time_us":10218,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29683,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:59.630573  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:18:59.683351  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.053s	user 0.017s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19094,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:59.683876  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:59.696727  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.697371  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:18:59.867596  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.170s	user 0.105s	sys 0.056s 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":227,"lbm_read_time_us":10254,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31681,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":65920,"update_count":2500}
I20260812 06:18:59.868340  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:18:59.933331  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.065s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22909,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.933889  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:18:59.946133  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.946938  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:00.137247  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.190s	user 0.112s	sys 0.068s 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":236,"lbm_read_time_us":13818,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31417,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:19:00.137769  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:19:00.201946  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.064s	user 0.039s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24044,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.202505  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:00.214205  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.214798  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushMRSOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:00.247146  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushMRSOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1388,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1658,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:00.247929  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling LogGCOp(7c2c93e925594fe2bba17f52395e507b): free 129320519 bytes of WAL
I20260812 06:19:00.248140  7110 log_reader.cc:385] T 7c2c93e925594fe2bba17f52395e507b: removed 13 log segments from log reader
I20260812 06:19:00.248184  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000015 (ops 71-75)
I20260812 06:19:00.248231  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000016 (ops 76-80)
I20260812 06:19:00.248256  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000017 (ops 81-85)
I20260812 06:19:00.248288  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000018 (ops 86-90)
I20260812 06:19:00.248313  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000019 (ops 91-95)
I20260812 06:19:00.248335  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000020 (ops 96-100)
I20260812 06:19:00.248361  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000021 (ops 101-105)
I20260812 06:19:00.248389  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000022 (ops 106-110)
I20260812 06:19:00.248409  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000023 (ops 111-114)
I20260812 06:19:00.248433  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000024 (ops 115-119)
I20260812 06:19:00.248471  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000025 (ops 120-124)
I20260812 06:19:00.248497  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000026 (ops 125-128)
I20260812 06:19:00.248519  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000027 (ops 129-133)
I20260812 06:19:00.282797  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: LogGCOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.035s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:19:00.283433  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:00.306751  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.023s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6312,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.307344  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:00.321892  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5671,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.322366  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:00.565429  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.243s	user 0.165s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":530,"lbm_read_time_us":17034,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44112,"lbm_writes_lt_1ms":743,"mutex_wait_us":73,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:19:00.566231  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=18.063937
I20260812 06:19:00.623440  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.057s	user 0.030s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26229,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:00.623932  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:00.634804  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.637117  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling UndoDeltaBlockGCOp(7c2c93e925594fe2bba17f52395e507b): 482 bytes on disk
I20260812 06:19:00.637625  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: UndoDeltaBlockGCOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.638183  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:00.815810  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.177s	user 0.136s	sys 0.040s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":373,"lbm_read_time_us":13293,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37181,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":3000}
I20260812 06:19:00.816533  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:19:00.876061  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.059s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24746,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.876740  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:00.904134  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.027s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6708,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:19:00.904603  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:00.915266  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.915781  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:01.091255  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.175s	user 0.135s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1070,"lbm_read_time_us":12311,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37893,"lbm_writes_lt_1ms":643,"mutex_wait_us":300,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":3000}
I20260812 06:19:01.091743  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:19:01.148962  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.057s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25706,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.149513  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:01.170763  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6126,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.171324  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:01.360976  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.189s	user 0.134s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":974,"lbm_read_time_us":11388,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35959,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2500}
I20260812 06:19:01.361768  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:19:01.412582  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.051s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22336,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.413362  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:01.567054  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.153s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":186,"lbm_read_time_us":9559,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26039,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:01.567744  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:19:01.623116  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.055s	user 0.023s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25458,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.623767  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:01.636395  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4620,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.637046  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushMRSOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:01.672222  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushMRSOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.035s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":258,"dirs.run_cpu_time_us":284,"dirs.run_wall_time_us":1634,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2146,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:01.673286  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling LogGCOp(7c2c93e925594fe2bba17f52395e507b): free 112239554 bytes of WAL
I20260812 06:19:01.673604  7110 log_reader.cc:385] T 7c2c93e925594fe2bba17f52395e507b: removed 11 log segments from log reader
I20260812 06:19:01.673681  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000028 (ops 134-138)
I20260812 06:19:01.673733  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000029 (ops 139-143)
I20260812 06:19:01.673790  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000030 (ops 144-148)
I20260812 06:19:01.673834  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000031 (ops 149-153)
I20260812 06:19:01.673877  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000032 (ops 154-158)
I20260812 06:19:01.673915  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000033 (ops 159-162)
I20260812 06:19:01.673954  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000034 (ops 163-167)
I20260812 06:19:01.673992  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000035 (ops 168-172)
I20260812 06:19:01.674032  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000036 (ops 173-177)
I20260812 06:19:01.674069  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000037 (ops 178-182)
I20260812 06:19:01.674108  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000038 (ops 183-187)
I20260812 06:19:01.699824  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: LogGCOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:01.700352  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:01.724437  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.024s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6151,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.724931  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling LogGCOp(7c2c93e925594fe2bba17f52395e507b): free 12017952 bytes of WAL
I20260812 06:19:01.725147  7110 log_reader.cc:385] T 7c2c93e925594fe2bba17f52395e507b: removed 1 log segments from log reader
I20260812 06:19:01.725189  7110 log.cc:1079] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/7c2c93e925594fe2bba17f52395e507b/wal-000000039 (ops 188-192)
I20260812 06:19:01.727473  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: LogGCOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:01.727792  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling UndoDeltaBlockGCOp(7c2c93e925594fe2bba17f52395e507b): 446 bytes on disk
I20260812 06:19:01.728216  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: UndoDeltaBlockGCOp(7c2c93e925594fe2bba17f52395e507b) 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:19:01.728794  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=2.188937
I20260812 06:19:01.739905  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3972,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.740446  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:01.929584  6942 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.009s	user 1.899s	sys 0.144s
I20260812 06:19:01.968955  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.228s	user 0.157s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979748,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":17827,"lbm_reads_lt_1ms":770,"lbm_write_time_us":39180,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:19:01.969662  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b): perf score=14.095187
I20260812 06:19:02.015097  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: FlushDeltaMemStoresOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.045s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20874,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.015609  7216 maintenance_manager.cc:419] P df4a86ee0e60480f93249ca80438b95c: Scheduling MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b): perf score=1.000000
I20260812 06:19:02.060248  6942 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.130s	user 0.002s	sys 0.000s
I20260812 06:19:02.061131  6942 tablet_server.cc:179] TabletServer@127.6.199.129:0 shutting down...
I20260812 06:19:02.147343  7110 maintenance_manager.cc:643] P df4a86ee0e60480f93249ca80438b95c: MajorDeltaCompactionOp(7c2c93e925594fe2bba17f52395e507b) complete. Timing: real 0.131s	user 0.096s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":655,"lbm_read_time_us":10122,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27849,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":651520,"update_count":2000}
I20260812 06:19:02.148221  6942 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:02.148656  6942 tablet_replica.cc:333] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c: stopping tablet replica
I20260812 06:19:02.148934  6942 raft_consensus.cc:2243] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.149191  6942 raft_consensus.cc:2272] T 7c2c93e925594fe2bba17f52395e507b P df4a86ee0e60480f93249ca80438b95c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.165611  6942 tablet_server.cc:196] TabletServer@127.6.199.129:0 shutdown complete.
I20260812 06:19:02.186913  6942 master.cc:562] Master@127.6.199.190:40359 shutting down...
I20260812 06:19:02.190941  6942 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.191118  6942 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.191174  6942 tablet_replica.cc:333] T 00000000000000000000000000000000 P bb7c47bb94384a8e87285c390392cc00: stopping tablet replica
I20260812 06:19:02.203585  6942 master.cc:584] Master@127.6.199.190:40359 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5676 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:02.303119  6942 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.199.190:44901
I20260812 06:19:02.303501  6942 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.306357  7271 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.306401  6942 server_base.cc:1061] running on GCE node
W20260812 06:19:02.306474  7267 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.306502  7264 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.306795  6942 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.306859  6942 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.306876  6942 hybrid_clock.cc:648] HybridClock initialized: now 1786515542306876 us; error 0 us; skew 500 ppm
I20260812 06:19:02.307905  6942 webserver.cc:533] Webserver started at http://127.6.199.190:38447/ using document root <none> and password file <none>
I20260812 06:19:02.308143  6942 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.308266  6942 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.308398  6942 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.308925  6942 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/master-0-root/instance:
uuid: "6ce58851a1a54056a26c00f43c7501a3"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-s11t"
I20260812 06:19:02.310716  6942 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:02.312004  7278 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.312371  6942 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:02.312486  6942 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/master-0-root
uuid: "6ce58851a1a54056a26c00f43c7501a3"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-s11t"
I20260812 06:19:02.312585  6942 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.328330  6942 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.328871  6942 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.333690  6942 rpc_server.cc:307] RPC server started. Bound to: 127.6.199.190:44901
I20260812 06:19:02.335350  7355 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.199.190:44901 every 8 connection(s)
I20260812 06:19:02.338275  7356 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.352569  7356 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3: Bootstrap starting.
I20260812 06:19:02.353498  7356 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.354699  7356 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3: No bootstrap required, opened a new log
I20260812 06:19:02.355202  7356 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6ce58851a1a54056a26c00f43c7501a3" member_type: VOTER }
I20260812 06:19:02.355302  7356 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.355325  7356 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6ce58851a1a54056a26c00f43c7501a3, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.355490  7356 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [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: "6ce58851a1a54056a26c00f43c7501a3" member_type: VOTER }
I20260812 06:19:02.355571  7356 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.355597  7356 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.355657  7356 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.356472  7356 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6ce58851a1a54056a26c00f43c7501a3" member_type: VOTER }
I20260812 06:19:02.356623  7356 leader_election.cc:304] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [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: 6ce58851a1a54056a26c00f43c7501a3; no voters: 
I20260812 06:19:02.356916  7356 leader_election.cc:290] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.357090  7362 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.357328  7362 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 1 LEADER]: Becoming Leader. State: Replica: 6ce58851a1a54056a26c00f43c7501a3, State: Running, Role: LEADER
I20260812 06:19:02.357456  7356 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:02.357491  7362 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [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: "6ce58851a1a54056a26c00f43c7501a3" member_type: VOTER }
I20260812 06:19:02.357969  7363 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6ce58851a1a54056a26c00f43c7501a3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6ce58851a1a54056a26c00f43c7501a3" member_type: VOTER } }
I20260812 06:19:02.358086  7363 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.357982  7365 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6ce58851a1a54056a26c00f43c7501a3. Latest consensus state: current_term: 1 leader_uuid: "6ce58851a1a54056a26c00f43c7501a3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6ce58851a1a54056a26c00f43c7501a3" member_type: VOTER } }
I20260812 06:19:02.358268  7365 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.358515  7369 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:02.359272  7369 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:02.359521  6942 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:02.361471  7369 catalog_manager.cc:1383] Generated new cluster ID: c7fe50546b2641629122b0042d5e99c5
I20260812 06:19:02.361542  7369 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:02.368790  7369 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:02.369372  7369 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:02.384202  7369 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3: Generated new TSK 0
I20260812 06:19:02.384471  7369 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:02.392217  6942 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:02.394619  6942 server_base.cc:1061] running on GCE node
W20260812 06:19:02.394613  7389 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.394691  7392 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.394629  7388 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.395080  6942 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.395128  6942 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.395171  6942 hybrid_clock.cc:648] HybridClock initialized: now 1786515542395170 us; error 0 us; skew 500 ppm
I20260812 06:19:02.396051  6942 webserver.cc:533] Webserver started at http://127.6.199.129:44623/ using document root <none> and password file <none>
I20260812 06:19:02.396245  6942 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.396294  6942 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.396425  6942 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.396935  6942 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/instance:
uuid: "868835f731794a34b3a80872f8ee5e0a"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-s11t"
I20260812 06:19:02.398465  6942 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:02.399468  7400 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.399897  6942 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:02.399964  6942 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root
uuid: "868835f731794a34b3a80872f8ee5e0a"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-s11t"
I20260812 06:19:02.400067  6942 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.420130  6942 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.420605  6942 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.421000  6942 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:02.421517  6942 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:02.421558  6942 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.421592  6942 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:02.421607  6942 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.426128  6942 rpc_server.cc:307] RPC server started. Bound to: 127.6.199.129:38591
I20260812 06:19:02.426789  7495 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.199.129:38591 every 8 connection(s)
I20260812 06:19:02.431733  7496 heartbeater.cc:344] Connected to a master server at 127.6.199.190:44901
I20260812 06:19:02.431838  7496 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:02.432085  7496 heartbeater.cc:507] Master 127.6.199.190:44901 requested a full tablet report, sending...
I20260812 06:19:02.432893  7297 ts_manager.cc:194] Registered new tserver with Master: 868835f731794a34b3a80872f8ee5e0a (127.6.199.129:38591)
I20260812 06:19:02.433640  7297 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57292
I20260812 06:19:02.433666  6942 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006796039s
I20260812 06:19:02.441525  7297 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57304:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:02.450964  7445 tablet_service.cc:1511] Processing CreateTablet for tablet 0daba6b965974abab23fc3a9ee73d592 (DEFAULT_TABLE table=heavy-update-compaction-test [id=823c387464e94e74a92c971e9599d338]), partition=
I20260812 06:19:02.451272  7445 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0daba6b965974abab23fc3a9ee73d592. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.453400  7520 tablet_bootstrap.cc:492] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Bootstrap starting.
I20260812 06:19:02.454295  7520 tablet_bootstrap.cc:654] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.455575  7520 tablet_bootstrap.cc:492] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: No bootstrap required, opened a new log
I20260812 06:19:02.455672  7520 ts_tablet_manager.cc:1403] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:02.456326  7520 raft_consensus.cc:359] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "868835f731794a34b3a80872f8ee5e0a" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 38591 } }
I20260812 06:19:02.456455  7520 raft_consensus.cc:385] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.456497  7520 raft_consensus.cc:740] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 868835f731794a34b3a80872f8ee5e0a, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.456727  7520 consensus_queue.cc:260] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [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: "868835f731794a34b3a80872f8ee5e0a" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 38591 } }
I20260812 06:19:02.456862  7520 raft_consensus.cc:399] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.456908  7520 raft_consensus.cc:493] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.456962  7520 raft_consensus.cc:3060] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.458055  7520 raft_consensus.cc:515] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "868835f731794a34b3a80872f8ee5e0a" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 38591 } }
I20260812 06:19:02.458209  7520 leader_election.cc:304] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [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: 868835f731794a34b3a80872f8ee5e0a; no voters: 
I20260812 06:19:02.458418  7520 leader_election.cc:290] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.458606  7525 raft_consensus.cc:2804] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.458822  7525 raft_consensus.cc:697] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 1 LEADER]: Becoming Leader. State: Replica: 868835f731794a34b3a80872f8ee5e0a, State: Running, Role: LEADER
I20260812 06:19:02.458861  7520 ts_tablet_manager.cc:1434] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:02.459110  7496 heartbeater.cc:499] Master 127.6.199.190:44901 was elected leader, sending a full tablet report...
I20260812 06:19:02.458986  7525 consensus_queue.cc:237] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [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: "868835f731794a34b3a80872f8ee5e0a" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 38591 } }
I20260812 06:19:02.460813  7297 catalog_manager.cc:5719] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a reported cstate change: term changed from 0 to 1, leader changed from <none> to 868835f731794a34b3a80872f8ee5e0a (127.6.199.129). New cstate: current_term: 1 leader_uuid: "868835f731794a34b3a80872f8ee5e0a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "868835f731794a34b3a80872f8ee5e0a" member_type: VOTER last_known_addr { host: "127.6.199.129" port: 38591 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:02.525748  6942 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.023s	sys 0.003s
I20260812 06:19:02.677424  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushMRSOp(0daba6b965974abab23fc3a9ee73d592): perf score=19.054940
I20260812 06:19:02.836163  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushMRSOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.158s	user 0.108s	sys 0.044s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":907,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41644,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:02.836875  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling LogGCOp(0daba6b965974abab23fc3a9ee73d592): free 20743880 bytes of WAL
I20260812 06:19:02.837105  7408 log_reader.cc:385] T 0daba6b965974abab23fc3a9ee73d592: removed 2 log segments from log reader
I20260812 06:19:02.837148  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000001 (ops 1-6)
I20260812 06:19:02.837178  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000002 (ops 7-11)
I20260812 06:19:02.841478  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: LogGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:02.841849  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:02.861207  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.019s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.861809  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:03.034041  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.172s	user 0.112s	sys 0.050s 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":583,"lbm_read_time_us":10190,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22932,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":321,"threads_started":5,"update_count":2000}
I20260812 06:19:03.034703  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling UndoDeltaBlockGCOp(0daba6b965974abab23fc3a9ee73d592): 16411392 bytes on disk
I20260812 06:19:03.035280  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: UndoDeltaBlockGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.035849  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=14.095187
I20260812 06:19:03.090348  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.054s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23716,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.090829  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:03.101609  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3956,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.102337  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:03.254570  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.152s	user 0.126s	sys 0.023s 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":1025,"lbm_read_time_us":9881,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30700,"lbm_writes_lt_1ms":543,"mutex_wait_us":387,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:19:03.255191  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=11.118625
I20260812 06:19:03.288143  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.033s	user 0.014s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14121,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:03.288729  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:03.303220  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5673,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.303687  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:03.435623  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.132s	user 0.096s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":670,"lbm_read_time_us":7957,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26850,"lbm_writes_lt_1ms":443,"mutex_wait_us":689,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:19:03.436703  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=10.126437
I20260812 06:19:03.490942  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.054s	user 0.027s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20038,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.491510  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:03.506552  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.507023  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:03.665359  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.158s	user 0.104s	sys 0.044s 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":1335,"lbm_read_time_us":10587,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22362,"lbm_writes_lt_1ms":443,"mutex_wait_us":567,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:19:03.666036  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=14.095187
I20260812 06:19:03.714141  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.048s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20612,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.714681  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:03.725767  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.726347  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:03.908851  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.182s	user 0.117s	sys 0.060s 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":221,"lbm_read_time_us":12465,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28855,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:19:03.909569  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=14.095187
I20260812 06:19:03.960904  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.051s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20498,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.961427  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:03.973409  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4463,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.973978  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:04.137490  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.163s	user 0.124s	sys 0.036s 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":389,"lbm_read_time_us":11496,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31360,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:04.138584  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=11.118625
I20260812 06:19:04.170665  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.032s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14019,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:04.171838  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:04.184553  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.185277  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushMRSOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:04.216470  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushMRSOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1323,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1472,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:04.217664  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling LogGCOp(0daba6b965974abab23fc3a9ee73d592): free 120553376 bytes of WAL
I20260812 06:19:04.218005  7408 log_reader.cc:385] T 0daba6b965974abab23fc3a9ee73d592: removed 12 log segments from log reader
I20260812 06:19:04.218120  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000003 (ops 12-16)
I20260812 06:19:04.218204  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000004 (ops 17-21)
I20260812 06:19:04.218253  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000005 (ops 22-26)
I20260812 06:19:04.218304  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000006 (ops 27-31)
I20260812 06:19:04.218348  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000007 (ops 32-36)
I20260812 06:19:04.218421  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000008 (ops 37-41)
I20260812 06:19:04.218484  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000009 (ops 42-46)
I20260812 06:19:04.218519  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000010 (ops 47-50)
I20260812 06:19:04.218588  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000011 (ops 51-55)
I20260812 06:19:04.218628  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000012 (ops 56-60)
I20260812 06:19:04.218673  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000013 (ops 61-64)
I20260812 06:19:04.218717  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000014 (ops 65-69)
I20260812 06:19:04.249779  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: LogGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:04.250393  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=5.165500
I20260812 06:19:04.271113  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.021s	user 0.005s	sys 0.013s Metrics: {"bytes_written":7056403,"delete_count":0,"lbm_write_time_us":8726,"lbm_writes_lt_1ms":175,"reinsert_count":0,"update_count":860}
I20260812 06:19:04.271940  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling LogGCOp(0daba6b965974abab23fc3a9ee73d592): free 12017932 bytes of WAL
I20260812 06:19:04.272195  7408 log_reader.cc:385] T 0daba6b965974abab23fc3a9ee73d592: removed 1 log segments from log reader
I20260812 06:19:04.272279  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000015 (ops 70-74)
I20260812 06:19:04.275156  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: LogGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:04.275548  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling UndoDeltaBlockGCOp(0daba6b965974abab23fc3a9ee73d592): 483 bytes on disk
I20260812 06:19:04.276127  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: UndoDeltaBlockGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.276629  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:04.286823  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.010s	user 0.001s	sys 0.004s Metrics: {"bytes_written":1148852,"delete_count":0,"lbm_write_time_us":2062,"lbm_writes_lt_1ms":31,"reinsert_count":0,"update_count":140}
I20260812 06:19:04.287452  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:04.508194  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.221s	user 0.142s	sys 0.070s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877261,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":329,"lbm_read_time_us":14201,"lbm_reads_lt_1ms":666,"lbm_write_time_us":33714,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:19:04.508853  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=18.063937
I20260812 06:19:04.580986  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.072s	user 0.044s	sys 0.028s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":27217,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.581601  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:04.592988  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.593452  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:04.804226  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.211s	user 0.146s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":653,"lbm_read_time_us":14954,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35212,"lbm_writes_lt_1ms":643,"mutex_wait_us":328,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":3000}
I20260812 06:19:04.804934  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=15.087375
I20260812 06:19:04.858577  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.053s	user 0.020s	sys 0.032s Metrics: {"bytes_written":16820139,"delete_count":0,"lbm_write_time_us":18601,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:04.859314  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:04.870909  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3905,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.871492  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:05.069442  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.198s	user 0.122s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774672,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1000,"lbm_read_time_us":14167,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29985,"lbm_writes_lt_1ms":543,"mutex_wait_us":79,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:05.070060  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=14.095187
I20260812 06:19:05.137902  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.068s	user 0.022s	sys 0.030s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18154,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.138523  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:05.154248  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.016s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.154784  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:05.352746  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.198s	user 0.132s	sys 0.057s 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":896,"lbm_read_time_us":13999,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30154,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:05.353530  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=14.095187
I20260812 06:19:05.408461  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.055s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22625,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.409006  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:05.420083  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.420958  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:05.601652  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.180s	user 0.105s	sys 0.065s 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":656,"lbm_read_time_us":10804,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27817,"lbm_writes_lt_1ms":543,"mutex_wait_us":287,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:19:05.602406  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=14.095187
I20260812 06:19:05.655167  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.053s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21739,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.655730  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:05.673177  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.017s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.673702  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushMRSOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:05.706898  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushMRSOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.033s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":189,"dirs.run_wall_time_us":1267,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2100,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:05.707775  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling LogGCOp(0daba6b965974abab23fc3a9ee73d592): free 112239323 bytes of WAL
I20260812 06:19:05.708065  7408 log_reader.cc:385] T 0daba6b965974abab23fc3a9ee73d592: removed 11 log segments from log reader
I20260812 06:19:05.708127  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000016 (ops 75-79)
I20260812 06:19:05.708166  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000017 (ops 80-84)
I20260812 06:19:05.708199  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000018 (ops 85-89)
I20260812 06:19:05.708223  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000019 (ops 90-94)
I20260812 06:19:05.708258  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000020 (ops 95-99)
I20260812 06:19:05.708292  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000021 (ops 100-104)
I20260812 06:19:05.708320  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000022 (ops 105-109)
I20260812 06:19:05.708349  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000023 (ops 110-114)
I20260812 06:19:05.708379  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000024 (ops 115-118)
I20260812 06:19:05.708407  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000025 (ops 119-123)
I20260812 06:19:05.708441  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000026 (ops 124-128)
I20260812 06:19:05.736841  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: LogGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:05.737237  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:05.765831  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.028s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.766379  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:05.781620  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.782085  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling UndoDeltaBlockGCOp(0daba6b965974abab23fc3a9ee73d592): 447 bytes on disk
I20260812 06:19:05.782487  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: UndoDeltaBlockGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.782979  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:06.028887  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.246s	user 0.127s	sys 0.111s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":776,"lbm_read_time_us":14961,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40247,"lbm_writes_lt_1ms":743,"mutex_wait_us":55,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":105,"threads_started":1,"update_count":3500}
I20260812 06:19:06.029443  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=18.063937
I20260812 06:19:06.100751  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.071s	user 0.044s	sys 0.016s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27358,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:06.101269  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:06.114455  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.114949  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:06.333673  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.219s	user 0.139s	sys 0.079s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1088,"lbm_read_time_us":15720,"lbm_reads_lt_1ms":668,"lbm_write_time_us":34601,"lbm_writes_lt_1ms":643,"mutex_wait_us":414,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3000}
I20260812 06:19:06.334537  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=18.063937
I20260812 06:19:06.411130  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.076s	user 0.045s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":30581,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:06.411710  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:06.423290  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.423813  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:06.639175  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.215s	user 0.147s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":790,"lbm_read_time_us":15300,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33639,"lbm_writes_lt_1ms":643,"mutex_wait_us":328,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":3000}
I20260812 06:19:06.639940  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=16.079562
I20260812 06:19:06.700260  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.060s	user 0.037s	sys 0.016s Metrics: {"bytes_written":17845750,"delete_count":0,"lbm_write_time_us":25276,"lbm_writes_lt_1ms":438,"reinsert_count":0,"update_count":2175}
I20260812 06:19:06.700966  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.196750
I20260812 06:19:06.710729  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.010s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3118063,"delete_count":0,"lbm_write_time_us":3237,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:19:06.711237  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:06.725399  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":5262,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:19:06.725963  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:06.940827  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.215s	user 0.147s	sys 0.067s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877193,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":194,"lbm_read_time_us":14347,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36319,"lbm_writes_lt_1ms":643,"mutex_wait_us":81,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:06.941648  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=14.095187
I20260812 06:19:07.001561  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.060s	user 0.042s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27534,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.002161  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=3.181125
I20260812 06:19:07.027927  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.026s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":6303,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:07.028467  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:07.038576  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3732,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.039038  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:07.248623  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.209s	user 0.153s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":139,"lbm_read_time_us":15180,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34051,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":26496,"update_count":3000}
I20260812 06:19:07.249559  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=14.095187
I20260812 06:19:07.308156  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.058s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20933,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.308768  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:07.319649  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.320135  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushMRSOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:07.354575  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushMRSOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.034s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":114,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1349,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1724,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:07.355302  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling LogGCOp(0daba6b965974abab23fc3a9ee73d592): free 121459762 bytes of WAL
I20260812 06:19:07.355564  7408 log_reader.cc:385] T 0daba6b965974abab23fc3a9ee73d592: removed 12 log segments from log reader
I20260812 06:19:07.355621  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000027 (ops 129-133)
I20260812 06:19:07.355659  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000028 (ops 134-138)
I20260812 06:19:07.355695  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000029 (ops 139-143)
I20260812 06:19:07.355724  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000030 (ops 144-148)
I20260812 06:19:07.355752  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000031 (ops 149-153)
I20260812 06:19:07.355780  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000032 (ops 154-158)
I20260812 06:19:07.355811  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000033 (ops 159-163)
I20260812 06:19:07.355844  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000034 (ops 164-168)
I20260812 06:19:07.355885  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000035 (ops 169-173)
I20260812 06:19:07.355908  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000036 (ops 174-178)
I20260812 06:19:07.355929  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000037 (ops 179-183)
I20260812 06:19:07.355952  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000038 (ops 184-188)
I20260812 06:19:07.385305  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: LogGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:07.385713  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling UndoDeltaBlockGCOp(0daba6b965974abab23fc3a9ee73d592): 482 bytes on disk
I20260812 06:19:07.386150  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: UndoDeltaBlockGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.386685  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:07.410413  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.024s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.410861  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling LogGCOp(0daba6b965974abab23fc3a9ee73d592): free 11564893 bytes of WAL
I20260812 06:19:07.411069  7408 log_reader.cc:385] T 0daba6b965974abab23fc3a9ee73d592: removed 1 log segments from log reader
I20260812 06:19:07.411114  7408 log.cc:1079] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: Deleting log segment in path: /tmp/dist-test-taskHwFz3V/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515536615906-6942-0/minicluster-data/ts-0-root/wals/0daba6b965974abab23fc3a9ee73d592/wal-000000039 (ops 189-192)
I20260812 06:19:07.413484  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: LogGCOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:07.413836  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=2.188937
I20260812 06:19:07.426024  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.426602  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:07.652086  6942 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.126s	user 1.916s	sys 0.226s
I20260812 06:19:07.680649  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.254s	user 0.176s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":18895,"lbm_reads_lt_1ms":770,"lbm_write_time_us":48418,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":3500}
I20260812 06:19:07.681209  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592): perf score=14.095187
I20260812 06:19:07.717531  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: FlushDeltaMemStoresOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.036s	user 0.026s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":15678,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.718135  7497 maintenance_manager.cc:419] P 868835f731794a34b3a80872f8ee5e0a: Scheduling MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592): perf score=1.000000
I20260812 06:19:07.726452  6942 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.074s	user 0.001s	sys 0.000s
I20260812 06:19:07.726989  6942 tablet_server.cc:179] TabletServer@127.6.199.129:0 shutting down...
I20260812 06:19:07.836658  7408 maintenance_manager.cc:643] P 868835f731794a34b3a80872f8ee5e0a: MajorDeltaCompactionOp(0daba6b965974abab23fc3a9ee73d592) complete. Timing: real 0.118s	user 0.093s	sys 0.025s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":827,"lbm_read_time_us":11438,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":466,"lbm_write_time_us":21714,"lbm_writes_lt_1ms":443,"mutex_wait_us":341,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:19:07.837585  6942 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:07.837935  6942 tablet_replica.cc:333] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a: stopping tablet replica
I20260812 06:19:07.838086  6942 raft_consensus.cc:2243] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.838281  6942 raft_consensus.cc:2272] T 0daba6b965974abab23fc3a9ee73d592 P 868835f731794a34b3a80872f8ee5e0a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.852483  6942 tablet_server.cc:196] TabletServer@127.6.199.129:0 shutdown complete.
I20260812 06:19:07.879487  6942 master.cc:562] Master@127.6.199.190:44901 shutting down...
I20260812 06:19:07.883927  6942 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.884164  6942 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.884268  6942 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6ce58851a1a54056a26c00f43c7501a3: stopping tablet replica
I20260812 06:19:07.896812  6942 master.cc:584] Master@127.6.199.190:44901 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5693 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11371 ms total)

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