[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:01.631155 29499 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.206.254:33989
I20260812 06:19:01.632216 29499 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:01.632905 29499 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:01.639789 29505 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:01.639814 29506 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:01.640089 29508 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:01.639876 29499 server_base.cc:1061] running on GCE node
I20260812 06:19:01.640605 29499 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:01.640698 29499 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:01.640749 29499 hybrid_clock.cc:648] HybridClock initialized: now 1786515541640746 us; error 0 us; skew 500 ppm
I20260812 06:19:01.642679 29499 webserver.cc:533] Webserver started at http://127.28.206.254:35787/ using document root <none> and password file <none>
I20260812 06:19:01.643239 29499 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:01.643303 29499 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:01.643549 29499 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:01.645249 29499 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/master-0-root/instance:
uuid: "1c774423a80b443c9e354be08e188310"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-gsp7"
I20260812 06:19:01.648950 29499 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:19:01.651409 29518 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:01.652452 29499 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:01.652581 29499 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/master-0-root
uuid: "1c774423a80b443c9e354be08e188310"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-gsp7"
I20260812 06:19:01.652694 29499 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-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:01.673060 29499 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:01.673880 29499 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:01.674086 29499 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:01.682456 29499 rpc_server.cc:307] RPC server started. Bound to: 127.28.206.254:33989
I20260812 06:19:01.682488 29600 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.206.254:33989 every 8 connection(s)
I20260812 06:19:01.684935 29601 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:01.691159 29601 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310: Bootstrap starting.
I20260812 06:19:01.693887 29601 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:01.695242 29601 log.cc:826] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:01.697166 29601 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310: No bootstrap required, opened a new log
I20260812 06:19:01.700166 29601 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1c774423a80b443c9e354be08e188310" member_type: VOTER }
I20260812 06:19:01.700354 29601 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:01.700436 29601 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1c774423a80b443c9e354be08e188310, State: Initialized, Role: FOLLOWER
I20260812 06:19:01.701082 29601 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [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: "1c774423a80b443c9e354be08e188310" member_type: VOTER }
I20260812 06:19:01.701257 29601 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:01.701368 29601 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:01.701565 29601 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:01.702464 29601 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1c774423a80b443c9e354be08e188310" member_type: VOTER }
I20260812 06:19:01.702943 29601 leader_election.cc:304] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [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: 1c774423a80b443c9e354be08e188310; no voters: 
I20260812 06:19:01.703336 29601 leader_election.cc:290] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:01.703496 29605 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:01.703815 29605 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 1 LEADER]: Becoming Leader. State: Replica: 1c774423a80b443c9e354be08e188310, State: Running, Role: LEADER
I20260812 06:19:01.704280 29605 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [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: "1c774423a80b443c9e354be08e188310" member_type: VOTER }
I20260812 06:19:01.704484 29601 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:01.706775 29608 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1c774423a80b443c9e354be08e188310. Latest consensus state: current_term: 1 leader_uuid: "1c774423a80b443c9e354be08e188310" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1c774423a80b443c9e354be08e188310" member_type: VOTER } }
I20260812 06:19:01.706781 29606 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1c774423a80b443c9e354be08e188310" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1c774423a80b443c9e354be08e188310" member_type: VOTER } }
I20260812 06:19:01.706914 29608 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:01.706928 29606 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:01.707079 29499 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:01.709128 29625 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:01.709220 29625 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:01.709362 29626 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:01.710147 29626 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:01.714751 29626 catalog_manager.cc:1383] Generated new cluster ID: 37607ae882964091b22d546b92f5f729
I20260812 06:19:01.714836 29626 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:01.722275 29626 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:01.723471 29626 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:01.736943 29626 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310: Generated new TSK 0
I20260812 06:19:01.737836 29626 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:01.739734 29499 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:01.742589 29643 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:01.742652 29636 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:01.742781 29638 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:01.743003 29499 server_base.cc:1061] running on GCE node
I20260812 06:19:01.743250 29499 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:01.743299 29499 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:01.743316 29499 hybrid_clock.cc:648] HybridClock initialized: now 1786515541743316 us; error 0 us; skew 500 ppm
I20260812 06:19:01.744364 29499 webserver.cc:533] Webserver started at http://127.28.206.193:33653/ using document root <none> and password file <none>
I20260812 06:19:01.744570 29499 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:01.744624 29499 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:01.744716 29499 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:01.745165 29499 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/instance:
uuid: "59c016e4ba284854ab2f1dfe0329a6d7"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-gsp7"
I20260812 06:19:01.746968 29499 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:01.748123 29650 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:01.748397 29499 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:01.748477 29499 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root
uuid: "59c016e4ba284854ab2f1dfe0329a6d7"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-gsp7"
I20260812 06:19:01.748592 29499 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-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:01.755065 29499 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:01.755548 29499 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:01.756112 29499 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:01.757022 29499 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:01.757077 29499 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.757153 29499 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:01.757192 29499 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.764897 29499 rpc_server.cc:307] RPC server started. Bound to: 127.28.206.193:38307
I20260812 06:19:01.764932 29769 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.206.193:38307 every 8 connection(s)
I20260812 06:19:01.780675 29772 heartbeater.cc:344] Connected to a master server at 127.28.206.254:33989
I20260812 06:19:01.780987 29772 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:01.781576 29772 heartbeater.cc:507] Master 127.28.206.254:33989 requested a full tablet report, sending...
I20260812 06:19:01.783341 29548 ts_manager.cc:194] Registered new tserver with Master: 59c016e4ba284854ab2f1dfe0329a6d7 (127.28.206.193:38307)
I20260812 06:19:01.783679 29499 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017974046s
I20260812 06:19:01.784984 29548 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44246
I20260812 06:19:01.794595 29548 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44260:
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:01.809032 29702 tablet_service.cc:1511] Processing CreateTablet for tablet 2b02b79b536e4c6e8a07f7bc203a5a26 (DEFAULT_TABLE table=heavy-update-compaction-test [id=cad2c0a8cb7b4ef6be6d881182da1dec]), partition=
I20260812 06:19:01.809552 29702 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2b02b79b536e4c6e8a07f7bc203a5a26. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:01.811815 29792 tablet_bootstrap.cc:492] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Bootstrap starting.
I20260812 06:19:01.812930 29792 tablet_bootstrap.cc:654] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:01.814085 29792 tablet_bootstrap.cc:492] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: No bootstrap required, opened a new log
I20260812 06:19:01.814168 29792 ts_tablet_manager.cc:1403] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:01.814623 29792 raft_consensus.cc:359] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "59c016e4ba284854ab2f1dfe0329a6d7" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 38307 } }
I20260812 06:19:01.814725 29792 raft_consensus.cc:385] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:01.814767 29792 raft_consensus.cc:740] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 59c016e4ba284854ab2f1dfe0329a6d7, State: Initialized, Role: FOLLOWER
I20260812 06:19:01.814934 29792 consensus_queue.cc:260] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [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: "59c016e4ba284854ab2f1dfe0329a6d7" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 38307 } }
I20260812 06:19:01.815017 29792 raft_consensus.cc:399] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:01.815063 29792 raft_consensus.cc:493] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:01.815124 29792 raft_consensus.cc:3060] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:01.815886 29792 raft_consensus.cc:515] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "59c016e4ba284854ab2f1dfe0329a6d7" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 38307 } }
I20260812 06:19:01.816051 29792 leader_election.cc:304] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [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: 59c016e4ba284854ab2f1dfe0329a6d7; no voters: 
I20260812 06:19:01.816275 29792 leader_election.cc:290] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:01.816394 29794 raft_consensus.cc:2804] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:01.816680 29794 raft_consensus.cc:697] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 1 LEADER]: Becoming Leader. State: Replica: 59c016e4ba284854ab2f1dfe0329a6d7, State: Running, Role: LEADER
I20260812 06:19:01.816732 29792 ts_tablet_manager.cc:1434] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:01.817154 29772 heartbeater.cc:499] Master 127.28.206.254:33989 was elected leader, sending a full tablet report...
I20260812 06:19:01.817124 29794 consensus_queue.cc:237] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [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: "59c016e4ba284854ab2f1dfe0329a6d7" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 38307 } }
I20260812 06:19:01.819836 29548 catalog_manager.cc:5719] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 59c016e4ba284854ab2f1dfe0329a6d7 (127.28.206.193). New cstate: current_term: 1 leader_uuid: "59c016e4ba284854ab2f1dfe0329a6d7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "59c016e4ba284854ab2f1dfe0329a6d7" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 38307 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:01.886121 29499 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.018s	sys 0.007s
I20260812 06:19:02.016324 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushMRSOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=19.054940
I20260812 06:19:02.194787 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushMRSOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.178s	user 0.136s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":280,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":799,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44483,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":216,"threads_started":1,"update_count":1500}
I20260812 06:19:02.196179 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): free 20743880 bytes of WAL
I20260812 06:19:02.196554 29660 log_reader.cc:385] T 2b02b79b536e4c6e8a07f7bc203a5a26: removed 2 log segments from log reader
I20260812 06:19:02.196679 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000001 (ops 1-6)
I20260812 06:19:02.196784 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000002 (ops 7-11)
I20260812 06:19:02.202247 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:02.202735 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=3.181125
I20260812 06:19:02.226619 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.024s	user 0.013s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6271,"lbm_writes_lt_1ms":113,"reinsert_count":0,"spinlock_wait_cycles":32128,"update_count":550}
I20260812 06:19:02.227206 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling UndoDeltaBlockGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): 16411399 bytes on disk
I20260812 06:19:02.227923 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: UndoDeltaBlockGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.228389 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:02.243026 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5606,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.243515 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:02.415014 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.171s	user 0.107s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774795,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":971,"lbm_read_time_us":11982,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28304,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20608,"thread_start_us":413,"threads_started":5,"update_count":2500}
I20260812 06:19:02.415628 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=10.126437
I20260812 06:19:02.446067 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.030s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13217,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.446511 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:02.459934 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.460448 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:02.595595 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.135s	user 0.113s	sys 0.021s 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":674,"lbm_read_time_us":8705,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26502,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30464,"update_count":2000}
I20260812 06:19:02.596244 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=10.126437
I20260812 06:19:02.647882 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.051s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17461,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.648372 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:02.659231 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.659958 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:02.788772 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.129s	user 0.111s	sys 0.017s 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":293,"lbm_read_time_us":8750,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23173,"lbm_writes_lt_1ms":443,"mutex_wait_us":84,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:19:02.789621 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=10.126437
I20260812 06:19:02.841418 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.052s	user 0.013s	sys 0.029s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21208,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.842024 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:02.857344 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.858008 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:02.989341 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.131s	user 0.106s	sys 0.024s 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":226,"lbm_read_time_us":8084,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27837,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.989984 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=10.126437
I20260812 06:19:03.043201 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.053s	user 0.030s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14023,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.043843 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:03.060688 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6457,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.061368 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:03.201016 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.139s	user 0.085s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":714,"lbm_read_time_us":11285,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21923,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.201747 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=10.126437
I20260812 06:19:03.243213 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.041s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17640,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.243784 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:03.259455 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.260073 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:03.379052 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.119s	user 0.098s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":694,"lbm_read_time_us":9699,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22075,"lbm_writes_lt_1ms":443,"mutex_wait_us":250,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:03.379714 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=10.126437
I20260812 06:19:03.420871 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.041s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15201,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.421411 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:03.433156 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.012s	user 0.001s	sys 0.008s 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:19:03.433704 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushMRSOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:03.464788 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushMRSOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1150,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1474,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":1920}
I20260812 06:19:03.465708 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): free 112239263 bytes of WAL
I20260812 06:19:03.465948 29660 log_reader.cc:385] T 2b02b79b536e4c6e8a07f7bc203a5a26: removed 11 log segments from log reader
I20260812 06:19:03.465993 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000003 (ops 12-16)
I20260812 06:19:03.466023 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000004 (ops 17-21)
I20260812 06:19:03.466085 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000005 (ops 22-26)
I20260812 06:19:03.466141 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000006 (ops 27-31)
I20260812 06:19:03.466179 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000007 (ops 32-36)
I20260812 06:19:03.466220 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000008 (ops 37-40)
I20260812 06:19:03.466259 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000009 (ops 41-45)
I20260812 06:19:03.466297 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000010 (ops 46-50)
I20260812 06:19:03.466336 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000011 (ops 51-55)
I20260812 06:19:03.466374 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000012 (ops 56-60)
I20260812 06:19:03.466413 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000013 (ops 61-65)
I20260812 06:19:03.491772 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:03.492324 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=3.181125
I20260812 06:19:03.505273 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4837,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:03.505842 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): free 12017983 bytes of WAL
I20260812 06:19:03.506106 29660 log_reader.cc:385] T 2b02b79b536e4c6e8a07f7bc203a5a26: removed 1 log segments from log reader
I20260812 06:19:03.506152 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000014 (ops 66-70)
I20260812 06:19:03.508709 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:03.509042 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:03.521061 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.521595 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:03.695868 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.174s	user 0.142s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":613,"lbm_read_time_us":13635,"lbm_reads_lt_1ms":666,"lbm_write_time_us":33050,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":27520,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:19:03.696565 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=14.095187
I20260812 06:19:03.744932 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.048s	user 0.012s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22056,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.745642 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:03.759172 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.759689 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:03.915045 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.155s	user 0.127s	sys 0.019s 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":824,"lbm_read_time_us":8769,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30025,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:19:03.915722 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=14.095187
I20260812 06:19:03.965504 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.050s	user 0.038s	sys 0.007s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21216,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.966164 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling UndoDeltaBlockGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): 462 bytes on disk
I20260812 06:19:03.966753 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: UndoDeltaBlockGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.967307 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:03.981148 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.981799 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:04.134135 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.152s	user 0.108s	sys 0.044s 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":480,"lbm_read_time_us":9646,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32274,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":74752,"update_count":2500}
I20260812 06:19:04.134713 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=11.118625
I20260812 06:19:04.168805 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.034s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15410,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:04.170363 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:04.186236 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.016s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5305,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.186748 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:04.314920 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.128s	user 0.096s	sys 0.032s 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":207,"lbm_read_time_us":8830,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23886,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:04.315619 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=10.126437
I20260812 06:19:04.364786 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.049s	user 0.015s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16184,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.365406 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:04.375942 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4003,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.376432 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:04.510164 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.134s	user 0.110s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":755,"lbm_read_time_us":10450,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21854,"lbm_writes_lt_1ms":443,"mutex_wait_us":264,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:19:04.512830 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=10.126437
I20260812 06:19:04.553257 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.040s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15751,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.553898 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:04.570403 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.016s	user 0.011s	sys 0.004s 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:19:04.570911 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:04.698972 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.128s	user 0.098s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1018,"lbm_read_time_us":10037,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25032,"lbm_writes_lt_1ms":443,"mutex_wait_us":643,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:19:04.699752 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=10.126437
I20260812 06:19:04.740289 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.040s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18601,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.740911 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:04.757115 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.757714 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushMRSOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:04.797851 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushMRSOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.040s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":181,"dirs.run_wall_time_us":1358,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2259,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:04.798949 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling UndoDeltaBlockGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): 462 bytes on disk
I20260812 06:19:04.799436 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: UndoDeltaBlockGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.800021 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=3.181125
I20260812 06:19:04.812377 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4651,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:04.812887 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): free 108535450 bytes of WAL
I20260812 06:19:04.813162 29660 log_reader.cc:385] T 2b02b79b536e4c6e8a07f7bc203a5a26: removed 11 log segments from log reader
I20260812 06:19:04.813225 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000015 (ops 71-75)
I20260812 06:19:04.813264 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000016 (ops 76-80)
I20260812 06:19:04.813295 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000017 (ops 81-84)
I20260812 06:19:04.813333 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000018 (ops 85-89)
I20260812 06:19:04.813359 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000019 (ops 90-94)
I20260812 06:19:04.813380 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000020 (ops 95-98)
I20260812 06:19:04.813410 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000021 (ops 99-103)
I20260812 06:19:04.813441 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000022 (ops 104-108)
I20260812 06:19:04.813470 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000023 (ops 109-113)
I20260812 06:19:04.813534 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000024 (ops 114-118)
I20260812 06:19:04.813566 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000025 (ops 119-123)
I20260812 06:19:04.840620 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.028s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:04.841173 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:04.867897 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.027s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5872,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.868423 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): free 12017932 bytes of WAL
I20260812 06:19:04.868649 29660 log_reader.cc:385] T 2b02b79b536e4c6e8a07f7bc203a5a26: removed 1 log segments from log reader
I20260812 06:19:04.868690 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000026 (ops 124-128)
I20260812 06:19:04.871008 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:04.871332 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:04.882668 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.011s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.883165 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:05.077343 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.194s	user 0.151s	sys 0.041s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":779,"lbm_read_time_us":12386,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37717,"lbm_writes_lt_1ms":743,"mutex_wait_us":523,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:19:05.078223 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=14.095187
I20260812 06:19:05.142376 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.064s	user 0.038s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24533,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.143078 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:05.162523 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.019s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6366,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.163074 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:05.346334 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.183s	user 0.130s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":603,"lbm_read_time_us":11995,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32460,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:05.346961 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=14.095187
I20260812 06:19:05.397922 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.051s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20180,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.398470 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:05.411211 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.412432 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:05.606241 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.194s	user 0.125s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":11193,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32758,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:05.607175 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=11.118625
I20260812 06:19:05.650334 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.043s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15472,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:05.650924 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:05.668519 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6504,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.669106 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:05.678768 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3516,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.679389 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:05.830919 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.151s	user 0.116s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":584,"lbm_read_time_us":10565,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31480,"lbm_writes_lt_1ms":543,"mutex_wait_us":156,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:05.831559 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=11.118625
I20260812 06:19:05.872568 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.041s	user 0.015s	sys 0.021s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":18026,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:05.873121 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:05.895350 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.022s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.895829 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:05.905972 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3502,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.906589 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:06.076746 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.170s	user 0.122s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":462,"lbm_read_time_us":11759,"lbm_reads_lt_1ms":573,"lbm_write_time_us":37147,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:06.077436 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=14.095187
I20260812 06:19:06.136619 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.059s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26465,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.137181 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:06.149712 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.012s	user 0.005s	sys 0.007s 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:06.150727 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:06.311581 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.161s	user 0.102s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":173,"lbm_read_time_us":12173,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32473,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:19:06.312191 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=14.095187
I20260812 06:19:06.373207 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.061s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25501,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.373823 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=2.188937
I20260812 06:19:06.388224 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5674,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.388693 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushMRSOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:06.423322 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushMRSOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1440,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1756,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:06.424057 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): free 121006640 bytes of WAL
I20260812 06:19:06.424294 29660 log_reader.cc:385] T 2b02b79b536e4c6e8a07f7bc203a5a26: removed 12 log segments from log reader
I20260812 06:19:06.424356 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000027 (ops 129-133)
I20260812 06:19:06.424410 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000028 (ops 134-138)
I20260812 06:19:06.424468 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000029 (ops 139-143)
I20260812 06:19:06.424508 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000030 (ops 144-148)
I20260812 06:19:06.424541 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000031 (ops 149-152)
I20260812 06:19:06.424578 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000032 (ops 153-157)
I20260812 06:19:06.424614 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000033 (ops 158-162)
I20260812 06:19:06.424652 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000034 (ops 163-167)
I20260812 06:19:06.424687 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000035 (ops 168-172)
I20260812 06:19:06.424726 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000036 (ops 173-177)
I20260812 06:19:06.424762 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000037 (ops 178-182)
I20260812 06:19:06.424806 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000038 (ops 183-187)
I20260812 06:19:06.451834 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:06.452373 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling UndoDeltaBlockGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): 492 bytes on disk
I20260812 06:19:06.452926 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: UndoDeltaBlockGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) 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:06.453578 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=5.165500
I20260812 06:19:06.470232 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":6851278,"delete_count":0,"lbm_write_time_us":7091,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:19:06.470747 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26): free 12018004 bytes of WAL
I20260812 06:19:06.471017 29660 log_reader.cc:385] T 2b02b79b536e4c6e8a07f7bc203a5a26: removed 1 log segments from log reader
I20260812 06:19:06.471091 29660 log.cc:1079] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/2b02b79b536e4c6e8a07f7bc203a5a26/wal-000000039 (ops 188-192)
I20260812 06:19:06.474112 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: LogGCOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:06.474604 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:06.487043 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.012s	user 0.007s	sys 0.001s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":2366,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:19:06.487560 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:06.654294 29499 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.768s	user 1.810s	sys 0.075s
I20260812 06:19:06.674167 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.186s	user 0.137s	sys 0.047s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979681,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":12532,"lbm_reads_lt_1ms":762,"lbm_write_time_us":37779,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3500}
I20260812 06:19:06.674757 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=14.095187
I20260812 06:19:06.711970 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: FlushDeltaMemStoresOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.037s	user 0.024s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18083,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:19:06.712558 29773 maintenance_manager.cc:419] P 59c016e4ba284854ab2f1dfe0329a6d7: Scheduling MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26): perf score=1.000000
I20260812 06:19:06.737741 29499 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.083s	user 0.003s	sys 0.000s
I20260812 06:19:06.738406 29499 tablet_server.cc:179] TabletServer@127.28.206.193:0 shutting down...
I20260812 06:19:06.839306 29660 maintenance_manager.cc:643] P 59c016e4ba284854ab2f1dfe0329a6d7: MajorDeltaCompactionOp(2b02b79b536e4c6e8a07f7bc203a5a26) complete. Timing: real 0.126s	user 0.113s	sys 0.011s 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":1030,"lbm_read_time_us":11113,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25572,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":200,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:19:06.839953 29499 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:06.840425 29499 tablet_replica.cc:333] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7: stopping tablet replica
I20260812 06:19:06.840674 29499 raft_consensus.cc:2243] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:06.840907 29499 raft_consensus.cc:2272] T 2b02b79b536e4c6e8a07f7bc203a5a26 P 59c016e4ba284854ab2f1dfe0329a6d7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:06.857846 29499 tablet_server.cc:196] TabletServer@127.28.206.193:0 shutdown complete.
I20260812 06:19:06.877619 29499 master.cc:562] Master@127.28.206.254:33989 shutting down...
I20260812 06:19:06.881397 29499 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:06.881668 29499 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:06.881749 29499 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1c774423a80b443c9e354be08e188310: stopping tablet replica
I20260812 06:19:06.894304 29499 master.cc:584] Master@127.28.206.254:33989 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5350 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:06.981205 29499 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.206.254:41541
I20260812 06:19:06.981705 29499 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:06.983772 29825 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:06.983908 29822 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:06.983928 29823 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:06.983989 29499 server_base.cc:1061] running on GCE node
I20260812 06:19:06.984261 29499 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:06.984305 29499 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:06.984321 29499 hybrid_clock.cc:648] HybridClock initialized: now 1786515546984321 us; error 0 us; skew 500 ppm
I20260812 06:19:06.985172 29499 webserver.cc:533] Webserver started at http://127.28.206.254:36071/ using document root <none> and password file <none>
I20260812 06:19:06.985311 29499 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:06.985352 29499 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:06.985404 29499 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:06.985826 29499 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/master-0-root/instance:
uuid: "c650cb4ca1784d65aec54463f6d1f331"
format_stamp: "Formatted at 2026-08-12 06:19:06 on dist-test-slave-gsp7"
I20260812 06:19:06.987351 29499 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:06.988258 29837 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:06.988530 29499 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:06.988620 29499 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/master-0-root
uuid: "c650cb4ca1784d65aec54463f6d1f331"
format_stamp: "Formatted at 2026-08-12 06:19:06 on dist-test-slave-gsp7"
I20260812 06:19:06.988710 29499 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-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:07.020006 29499 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:07.020457 29499 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:07.024734 29499 rpc_server.cc:307] RPC server started. Bound to: 127.28.206.254:41541
I20260812 06:19:07.027392 29924 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.206.254:41541 every 8 connection(s)
I20260812 06:19:07.027458 29927 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:07.040835 29927 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331: Bootstrap starting.
I20260812 06:19:07.041803 29927 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:07.042870 29927 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331: No bootstrap required, opened a new log
I20260812 06:19:07.043292 29927 raft_consensus.cc:359] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c650cb4ca1784d65aec54463f6d1f331" member_type: VOTER }
I20260812 06:19:07.043382 29927 raft_consensus.cc:385] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:07.043427 29927 raft_consensus.cc:740] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c650cb4ca1784d65aec54463f6d1f331, State: Initialized, Role: FOLLOWER
I20260812 06:19:07.043612 29927 consensus_queue.cc:260] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [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: "c650cb4ca1784d65aec54463f6d1f331" member_type: VOTER }
I20260812 06:19:07.043706 29927 raft_consensus.cc:399] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:07.043771 29927 raft_consensus.cc:493] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:07.043833 29927 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:07.044551 29927 raft_consensus.cc:515] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c650cb4ca1784d65aec54463f6d1f331" member_type: VOTER }
I20260812 06:19:07.044700 29927 leader_election.cc:304] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [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: c650cb4ca1784d65aec54463f6d1f331; no voters: 
I20260812 06:19:07.044921 29927 leader_election.cc:290] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:07.045076 29931 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:07.045337 29931 raft_consensus.cc:697] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 1 LEADER]: Becoming Leader. State: Replica: c650cb4ca1784d65aec54463f6d1f331, State: Running, Role: LEADER
I20260812 06:19:07.045523 29927 sys_catalog.cc:565] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:07.045498 29931 consensus_queue.cc:237] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [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: "c650cb4ca1784d65aec54463f6d1f331" member_type: VOTER }
I20260812 06:19:07.046015 29935 sys_catalog.cc:455] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c650cb4ca1784d65aec54463f6d1f331. Latest consensus state: current_term: 1 leader_uuid: "c650cb4ca1784d65aec54463f6d1f331" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c650cb4ca1784d65aec54463f6d1f331" member_type: VOTER } }
I20260812 06:19:07.045995 29932 sys_catalog.cc:455] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c650cb4ca1784d65aec54463f6d1f331" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c650cb4ca1784d65aec54463f6d1f331" member_type: VOTER } }
I20260812 06:19:07.046140 29935 sys_catalog.cc:458] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:07.046205 29932 sys_catalog.cc:458] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:07.046715 29941 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:07.047385 29941 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:07.047694 29499 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:07.049186 29941 catalog_manager.cc:1383] Generated new cluster ID: 17de5f4c6a3342b5805f267124b61a21
I20260812 06:19:07.049243 29941 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:07.058745 29941 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:07.059365 29941 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:07.065995 29941 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331: Generated new TSK 0
I20260812 06:19:07.066216 29941 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:07.080271 29499 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:07.082450 29962 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:07.082528 29960 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:07.082604 29959 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:07.082631 29499 server_base.cc:1061] running on GCE node
I20260812 06:19:07.082908 29499 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:07.082962 29499 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:07.082978 29499 hybrid_clock.cc:648] HybridClock initialized: now 1786515547082978 us; error 0 us; skew 500 ppm
I20260812 06:19:07.083781 29499 webserver.cc:533] Webserver started at http://127.28.206.193:46271/ using document root <none> and password file <none>
I20260812 06:19:07.083940 29499 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:07.083998 29499 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:07.084053 29499 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:07.084417 29499 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/instance:
uuid: "af89c65b908c4f5689c045ce7be0dc7c"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-gsp7"
I20260812 06:19:07.085991 29499 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:07.086903 29971 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:07.087139 29499 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:07.087203 29499 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root
uuid: "af89c65b908c4f5689c045ce7be0dc7c"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-gsp7"
I20260812 06:19:07.087309 29499 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-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:07.107056 29499 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:07.107510 29499 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:07.107862 29499 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:07.108376 29499 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:07.108415 29499 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.108479 29499 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:07.108520 29499 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.113117 29499 rpc_server.cc:307] RPC server started. Bound to: 127.28.206.193:36165
I20260812 06:19:07.113157 30071 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.206.193:36165 every 8 connection(s)
I20260812 06:19:07.123157 30074 heartbeater.cc:344] Connected to a master server at 127.28.206.254:41541
I20260812 06:19:07.123310 30074 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:07.123632 30074 heartbeater.cc:507] Master 127.28.206.254:41541 requested a full tablet report, sending...
I20260812 06:19:07.124298 29862 ts_manager.cc:194] Registered new tserver with Master: af89c65b908c4f5689c045ce7be0dc7c (127.28.206.193:36165)
I20260812 06:19:07.124660 29499 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011057418s
I20260812 06:19:07.125303 29862 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42344
I20260812 06:19:07.131845 29862 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42350:
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:07.140769 30015 tablet_service.cc:1511] Processing CreateTablet for tablet 356f296412fb41f3a5bcf0b6746b8982 (DEFAULT_TABLE table=heavy-update-compaction-test [id=60cc7d6ce9ea4ecf94662add0f0428a0]), partition=
I20260812 06:19:07.141045 30015 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 356f296412fb41f3a5bcf0b6746b8982. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:07.143177 30100 tablet_bootstrap.cc:492] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Bootstrap starting.
I20260812 06:19:07.144114 30100 tablet_bootstrap.cc:654] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:07.145220 30100 tablet_bootstrap.cc:492] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: No bootstrap required, opened a new log
I20260812 06:19:07.145299 30100 ts_tablet_manager.cc:1403] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:07.145761 30100 raft_consensus.cc:359] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af89c65b908c4f5689c045ce7be0dc7c" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 36165 } }
I20260812 06:19:07.145886 30100 raft_consensus.cc:385] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:07.145943 30100 raft_consensus.cc:740] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: af89c65b908c4f5689c045ce7be0dc7c, State: Initialized, Role: FOLLOWER
I20260812 06:19:07.146096 30100 consensus_queue.cc:260] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [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: "af89c65b908c4f5689c045ce7be0dc7c" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 36165 } }
I20260812 06:19:07.146201 30100 raft_consensus.cc:399] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:07.146247 30100 raft_consensus.cc:493] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:07.146299 30100 raft_consensus.cc:3060] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:07.147194 30100 raft_consensus.cc:515] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af89c65b908c4f5689c045ce7be0dc7c" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 36165 } }
I20260812 06:19:07.147405 30100 leader_election.cc:304] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [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: af89c65b908c4f5689c045ce7be0dc7c; no voters: 
I20260812 06:19:07.147636 30100 leader_election.cc:290] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:07.147816 30103 raft_consensus.cc:2804] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:07.147955 30100 ts_tablet_manager.cc:1434] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:07.147975 30074 heartbeater.cc:499] Master 127.28.206.254:41541 was elected leader, sending a full tablet report...
I20260812 06:19:07.148078 30103 raft_consensus.cc:697] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 1 LEADER]: Becoming Leader. State: Replica: af89c65b908c4f5689c045ce7be0dc7c, State: Running, Role: LEADER
I20260812 06:19:07.148231 30103 consensus_queue.cc:237] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [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: "af89c65b908c4f5689c045ce7be0dc7c" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 36165 } }
I20260812 06:19:07.149765 29862 catalog_manager.cc:5719] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c reported cstate change: term changed from 0 to 1, leader changed from <none> to af89c65b908c4f5689c045ce7be0dc7c (127.28.206.193). New cstate: current_term: 1 leader_uuid: "af89c65b908c4f5689c045ce7be0dc7c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af89c65b908c4f5689c045ce7be0dc7c" member_type: VOTER last_known_addr { host: "127.28.206.193" port: 36165 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:07.209690 29499 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.015s	sys 0.008s
I20260812 06:19:07.364032 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushMRSOp(356f296412fb41f3a5bcf0b6746b8982): perf score=19.054940
I20260812 06:19:07.512524 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushMRSOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.148s	user 0.097s	sys 0.048s Metrics: {"bytes_written":12020322,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":167,"dirs.run_cpu_time_us":190,"dirs.run_wall_time_us":998,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37193,"lbm_writes_lt_1ms":760,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1920,"update_count":1465}
I20260812 06:19:07.513381 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling LogGCOp(356f296412fb41f3a5bcf0b6746b8982): free 20743880 bytes of WAL
I20260812 06:19:07.513619 29980 log_reader.cc:385] T 356f296412fb41f3a5bcf0b6746b8982: removed 2 log segments from log reader
I20260812 06:19:07.513723 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000001 (ops 1-6)
I20260812 06:19:07.513800 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000002 (ops 7-11)
I20260812 06:19:07.518666 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: LogGCOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:07.519059 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=3.181125
I20260812 06:19:07.538282 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.019s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4389834,"delete_count":0,"lbm_write_time_us":4733,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:19:07.538913 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling UndoDeltaBlockGCOp(356f296412fb41f3a5bcf0b6746b8982): 16821645 bytes on disk
I20260812 06:19:07.539708 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: UndoDeltaBlockGCOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.540117 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:07.550025 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3681,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.550446 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:07.716500 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.166s	user 0.113s	sys 0.044s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405556,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":591,"lbm_read_time_us":11405,"lbm_reads_lt_1ms":559,"lbm_write_time_us":28669,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":338,"threads_started":5,"update_count":2450}
I20260812 06:19:07.717160 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=14.095187
I20260812 06:19:07.765746 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.048s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18955,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.766314 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:07.781912 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.015s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.782428 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:07.952494 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.170s	user 0.117s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":887,"lbm_read_time_us":11722,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31580,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:19:07.953130 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=12.110812
I20260812 06:19:07.988660 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.035s	user 0.015s	sys 0.017s Metrics: {"bytes_written":14071526,"delete_count":0,"lbm_write_time_us":15165,"lbm_writes_lt_1ms":346,"reinsert_count":0,"update_count":1715}
I20260812 06:19:07.989269 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.196750
I20260812 06:19:08.000918 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":3804,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:19:08.001379 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:08.149367 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.148s	user 0.087s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713228,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":9027,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23138,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":63360,"update_count":2000}
I20260812 06:19:08.150211 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=14.095187
I20260812 06:19:08.200155 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.050s	user 0.035s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19587,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.200722 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:08.225227 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.024s	user 0.014s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.225893 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:08.431473 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.205s	user 0.133s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":14785,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31456,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:19:08.432147 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=11.118625
I20260812 06:19:08.470139 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.037s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16541,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:08.470615 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:08.484091 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4676,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.484856 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:08.613507 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.128s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":582,"lbm_read_time_us":9512,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23824,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24192,"update_count":2000}
I20260812 06:19:08.614226 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=6.157687
I20260812 06:19:08.644371 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.030s	user 0.012s	sys 0.014s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":12474,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:08.645135 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:08.748325 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.103s	user 0.079s	sys 0.024s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12508328,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1061,"lbm_read_time_us":6606,"lbm_reads_lt_1ms":267,"lbm_write_time_us":16460,"lbm_writes_lt_1ms":243,"mutex_wait_us":39,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":1000}
I20260812 06:19:08.749116 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=6.157687
I20260812 06:19:08.788826 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.039s	user 0.015s	sys 0.011s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12401,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:08.789746 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:08.808806 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7095,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.809420 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:08.923442 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.114s	user 0.084s	sys 0.029s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16610860,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":11022,"lbm_reads_lt_1ms":372,"lbm_write_time_us":18030,"lbm_writes_lt_1ms":343,"mutex_wait_us":65,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:08.924248 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=10.126437
I20260812 06:19:08.963531 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.039s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19145,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.964080 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:08.975019 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.975775 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushMRSOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:09.008972 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushMRSOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1551,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2131,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:09.009662 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling LogGCOp(356f296412fb41f3a5bcf0b6746b8982): free 133024372 bytes of WAL
I20260812 06:19:09.009898 29980 log_reader.cc:385] T 356f296412fb41f3a5bcf0b6746b8982: removed 13 log segments from log reader
I20260812 06:19:09.009941 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000003 (ops 12-16)
I20260812 06:19:09.009971 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000004 (ops 17-21)
I20260812 06:19:09.010059 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000005 (ops 22-26)
I20260812 06:19:09.010125 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000006 (ops 27-31)
I20260812 06:19:09.010165 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000007 (ops 32-36)
I20260812 06:19:09.010214 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000008 (ops 37-41)
I20260812 06:19:09.010253 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000009 (ops 42-46)
I20260812 06:19:09.010293 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000010 (ops 47-51)
I20260812 06:19:09.010334 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000011 (ops 52-56)
I20260812 06:19:09.010375 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000012 (ops 57-61)
I20260812 06:19:09.010416 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000013 (ops 62-66)
I20260812 06:19:09.010468 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000014 (ops 67-70)
I20260812 06:19:09.010505 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000015 (ops 71-75)
I20260812 06:19:09.037375 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: LogGCOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:09.037845 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling UndoDeltaBlockGCOp(356f296412fb41f3a5bcf0b6746b8982): 482 bytes on disk
I20260812 06:19:09.038295 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: UndoDeltaBlockGCOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.038875 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=3.181125
I20260812 06:19:09.050997 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4500,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:09.051497 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:09.065445 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5083,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.066001 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:09.245139 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.179s	user 0.138s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":621,"lbm_read_time_us":11461,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35412,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:19:09.245810 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=14.095187
I20260812 06:19:09.291531 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.046s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19138,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.292060 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:09.307228 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5712,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.307838 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:09.459654 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.152s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":9931,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29877,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:09.460678 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=10.126437
I20260812 06:19:09.505712 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.045s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17227,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.506333 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:09.523682 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.524353 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:09.689987 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.165s	user 0.102s	sys 0.063s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":12424,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30091,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:09.690627 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=10.126437
I20260812 06:19:09.728410 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.038s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16222,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.729030 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:09.748646 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.019s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6160,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.749152 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:09.921708 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.172s	user 0.110s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2116,"lbm_read_time_us":8979,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25296,"lbm_writes_lt_1ms":443,"mutex_wait_us":1208,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:19:09.922564 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=14.095187
I20260812 06:19:09.976183 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.053s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22180,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.976738 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:09.987393 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3917,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.988070 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:10.132808 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.144s	user 0.107s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1644,"lbm_read_time_us":9274,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29912,"lbm_writes_lt_1ms":543,"mutex_wait_us":799,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:10.133570 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=10.126437
I20260812 06:19:10.171826 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.038s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15407,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.172466 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:10.187455 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.188019 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:10.310289 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.122s	user 0.089s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":119,"lbm_read_time_us":8855,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23017,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:19:10.311450 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=10.126437
I20260812 06:19:10.359335 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.048s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18414,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:19:10.360040 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:10.371045 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.371559 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushMRSOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:10.409240 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushMRSOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.037s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":173,"dirs.run_wall_time_us":1191,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2197,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:10.409915 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling LogGCOp(356f296412fb41f3a5bcf0b6746b8982): free 112239318 bytes of WAL
I20260812 06:19:10.410176 29980 log_reader.cc:385] T 356f296412fb41f3a5bcf0b6746b8982: removed 11 log segments from log reader
I20260812 06:19:10.410221 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000016 (ops 76-80)
I20260812 06:19:10.410250 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000017 (ops 81-85)
I20260812 06:19:10.410316 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000018 (ops 86-90)
I20260812 06:19:10.410359 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000019 (ops 91-95)
I20260812 06:19:10.410410 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000020 (ops 96-100)
I20260812 06:19:10.410475 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000021 (ops 101-104)
I20260812 06:19:10.410517 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000022 (ops 105-109)
I20260812 06:19:10.410557 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000023 (ops 110-114)
I20260812 06:19:10.410598 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000024 (ops 115-119)
I20260812 06:19:10.410638 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000025 (ops 120-124)
I20260812 06:19:10.410677 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000026 (ops 125-129)
I20260812 06:19:10.434532 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: LogGCOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:10.434926 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling UndoDeltaBlockGCOp(356f296412fb41f3a5bcf0b6746b8982): 448 bytes on disk
I20260812 06:19:10.435340 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: UndoDeltaBlockGCOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.435863 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=3.181125
I20260812 06:19:10.460031 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.024s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6489,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:10.460574 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:10.470326 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3614,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:10.470985 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:10.677903 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.207s	user 0.139s	sys 0.066s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":632,"lbm_read_time_us":15671,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34320,"lbm_writes_lt_1ms":643,"mutex_wait_us":90,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:19:10.678691 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=14.095187
I20260812 06:19:10.734807 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.056s	user 0.040s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24046,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.735385 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:10.905277 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.170s	user 0.109s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":737,"lbm_read_time_us":11154,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27004,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2000}
I20260812 06:19:10.905997 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=14.095187
I20260812 06:19:10.957361 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.051s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19211,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.958012 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:10.970934 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4785,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.971509 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:11.173453 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.202s	user 0.133s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":877,"lbm_read_time_us":14397,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32508,"lbm_writes_lt_1ms":543,"mutex_wait_us":325,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":45824,"update_count":2500}
I20260812 06:19:11.174124 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=14.095187
I20260812 06:19:11.226579 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.052s	user 0.033s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23515,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.227216 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:11.245054 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.245656 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:11.418509 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.173s	user 0.120s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":323,"lbm_read_time_us":12418,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34713,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:19:11.419296 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=14.095187
I20260812 06:19:11.472432 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.053s	user 0.042s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23963,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.473001 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:11.485057 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.485909 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:11.636898 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.151s	user 0.105s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":10683,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30317,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:11.637809 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=11.118625
I20260812 06:19:11.684046 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.046s	user 0.019s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20209,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:11.684772 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:11.704735 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.020s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.705284 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:11.719483 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5425,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:11.720126 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:11.868117 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.148s	user 0.104s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":181,"lbm_read_time_us":10734,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32237,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:19:11.869781 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=10.126437
I20260812 06:19:11.908362 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.038s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17430,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.908958 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=2.188937
I20260812 06:19:11.924381 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.924856 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushMRSOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:11.951659 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushMRSOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.027s	user 0.022s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1395,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1935,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":2304}
I20260812 06:19:11.952358 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling LogGCOp(356f296412fb41f3a5bcf0b6746b8982): free 128867668 bytes of WAL
I20260812 06:19:11.952610 29980 log_reader.cc:385] T 356f296412fb41f3a5bcf0b6746b8982: removed 13 log segments from log reader
I20260812 06:19:11.952677 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000027 (ops 130-134)
I20260812 06:19:11.952730 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000028 (ops 135-138)
I20260812 06:19:11.952790 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000029 (ops 139-143)
I20260812 06:19:11.952834 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000030 (ops 144-148)
I20260812 06:19:11.952883 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000031 (ops 149-153)
I20260812 06:19:11.952924 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000032 (ops 154-158)
I20260812 06:19:11.952963 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000033 (ops 159-162)
I20260812 06:19:11.953003 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000034 (ops 163-167)
I20260812 06:19:11.953040 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000035 (ops 168-172)
I20260812 06:19:11.953080 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000036 (ops 173-176)
I20260812 06:19:11.953120 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000037 (ops 177-181)
I20260812 06:19:11.953187 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000038 (ops 182-186)
I20260812 06:19:11.953230 29980 log.cc:1079] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: Deleting log segment in path: /tmp/dist-test-taskZiGF7k/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620254-29499-0/minicluster-data/ts-0-root/wals/356f296412fb41f3a5bcf0b6746b8982/wal-000000039 (ops 187-191)
I20260812 06:19:11.983282 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: LogGCOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:11.983731 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=6.157687
I20260812 06:19:12.010131 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.026s	user 0.018s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10282,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:12.010690 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling UndoDeltaBlockGCOp(356f296412fb41f3a5bcf0b6746b8982): 482 bytes on disk
I20260812 06:19:12.011221 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: UndoDeltaBlockGCOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:19:12.011855 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982): perf score=1.000000
I20260812 06:19:12.181572 29499 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.972s	user 1.879s	sys 0.135s
I20260812 06:19:12.185396 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: MajorDeltaCompactionOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.173s	user 0.145s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918216,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":358,"lbm_read_time_us":12985,"lbm_reads_lt_1ms":665,"lbm_write_time_us":34959,"lbm_writes_lt_1ms":643,"mutex_wait_us":86,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":114,"threads_started":1,"update_count":3000}
I20260812 06:19:12.186116 30080 maintenance_manager.cc:419] P af89c65b908c4f5689c045ce7be0dc7c: Scheduling FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982): perf score=14.095187
I20260812 06:19:12.211953 29499 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.030s	user 0.001s	sys 0.000s
I20260812 06:19:12.212508 29499 tablet_server.cc:179] TabletServer@127.28.206.193:0 shutting down...
I20260812 06:19:12.237084 29980 maintenance_manager.cc:643] P af89c65b908c4f5689c045ce7be0dc7c: FlushDeltaMemStoresOp(356f296412fb41f3a5bcf0b6746b8982) complete. Timing: real 0.051s	user 0.041s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23488,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.237782 29499 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:12.238034 29499 tablet_replica.cc:333] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c: stopping tablet replica
I20260812 06:19:12.238191 29499 raft_consensus.cc:2243] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:12.238381 29499 raft_consensus.cc:2272] T 356f296412fb41f3a5bcf0b6746b8982 P af89c65b908c4f5689c045ce7be0dc7c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:12.253194 29499 tablet_server.cc:196] TabletServer@127.28.206.193:0 shutdown complete.
I20260812 06:19:12.256428 29499 master.cc:562] Master@127.28.206.254:41541 shutting down...
I20260812 06:19:12.260104 29499 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:12.260308 29499 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:12.260402 29499 tablet_replica.cc:333] T 00000000000000000000000000000000 P c650cb4ca1784d65aec54463f6d1f331: stopping tablet replica
I20260812 06:19:12.273090 29499 master.cc:584] Master@127.28.206.254:41541 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5379 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10731 ms total)

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