[==========] 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:16:57.304930 24679 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.25.254:38725
I20260812 06:16:57.306038 24679 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:16:57.306661 24679 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:57.313460 24691 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:16:57.313506 24687 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:16:57.313601 24679 server_base.cc:1061] running on GCE node
W20260812 06:16:57.313799 24688 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:16:57.314354 24679 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:57.314445 24679 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:16:57.314471 24679 hybrid_clock.cc:648] HybridClock initialized: now 1786515417314469 us; error 0 us; skew 500 ppm
I20260812 06:16:57.316344 24679 webserver.cc:533] Webserver started at http://127.24.25.254:44651/ using document root <none> and password file <none>
I20260812 06:16:57.316866 24679 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:57.316923 24679 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:57.317117 24679 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:57.318810 24679 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/master-0-root/instance:
uuid: "28b114d7a0ba41dd991a351c7b3ce710"
format_stamp: "Formatted at 2026-08-12 06:16:57 on dist-test-slave-gkw7"
I20260812 06:16:57.322460 24679 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:16:57.324512 24700 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:16:57.325618 24679 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:16:57.325742 24679 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/master-0-root
uuid: "28b114d7a0ba41dd991a351c7b3ce710"
format_stamp: "Formatted at 2026-08-12 06:16:57 on dist-test-slave-gkw7"
I20260812 06:16:57.325847 24679 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-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:16:57.375986 24679 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:57.376731 24679 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:16:57.376927 24679 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:57.385200 24679 rpc_server.cc:307] RPC server started. Bound to: 127.24.25.254:38725
I20260812 06:16:57.385231 24785 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.25.254:38725 every 8 connection(s)
I20260812 06:16:57.387739 24787 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:16:57.393743 24787 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710: Bootstrap starting.
I20260812 06:16:57.396425 24787 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:57.397416 24787 log.cc:826] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:57.399349 24787 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710: No bootstrap required, opened a new log
I20260812 06:16:57.402441 24787 raft_consensus.cc:359] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28b114d7a0ba41dd991a351c7b3ce710" member_type: VOTER }
I20260812 06:16:57.402614 24787 raft_consensus.cc:385] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:57.402662 24787 raft_consensus.cc:740] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 28b114d7a0ba41dd991a351c7b3ce710, State: Initialized, Role: FOLLOWER
I20260812 06:16:57.403231 24787 consensus_queue.cc:260] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [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: "28b114d7a0ba41dd991a351c7b3ce710" member_type: VOTER }
I20260812 06:16:57.403368 24787 raft_consensus.cc:399] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:57.403419 24787 raft_consensus.cc:493] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:57.403506 24787 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:57.404294 24787 raft_consensus.cc:515] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28b114d7a0ba41dd991a351c7b3ce710" member_type: VOTER }
I20260812 06:16:57.404698 24787 leader_election.cc:304] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [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: 28b114d7a0ba41dd991a351c7b3ce710; no voters: 
I20260812 06:16:57.405014 24787 leader_election.cc:290] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:57.405095 24791 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:57.405367 24791 raft_consensus.cc:697] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 1 LEADER]: Becoming Leader. State: Replica: 28b114d7a0ba41dd991a351c7b3ce710, State: Running, Role: LEADER
I20260812 06:16:57.405840 24791 consensus_queue.cc:237] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [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: "28b114d7a0ba41dd991a351c7b3ce710" member_type: VOTER }
I20260812 06:16:57.406101 24787 sys_catalog.cc:565] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:57.407765 24793 sys_catalog.cc:455] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "28b114d7a0ba41dd991a351c7b3ce710" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28b114d7a0ba41dd991a351c7b3ce710" member_type: VOTER } }
I20260812 06:16:57.407754 24795 sys_catalog.cc:455] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 28b114d7a0ba41dd991a351c7b3ce710. Latest consensus state: current_term: 1 leader_uuid: "28b114d7a0ba41dd991a351c7b3ce710" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28b114d7a0ba41dd991a351c7b3ce710" member_type: VOTER } }
I20260812 06:16:57.407903 24793 sys_catalog.cc:458] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:57.407903 24795 sys_catalog.cc:458] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:57.408327 24809 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:57.408545 24679 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:57.410728 24809 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:57.415251 24809 catalog_manager.cc:1383] Generated new cluster ID: c8c8fe5c364a452ba79da98bd2d8e80e
I20260812 06:16:57.415319 24809 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:57.432668 24809 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:57.433614 24809 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:57.439801 24809 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710: Generated new TSK 0
I20260812 06:16:57.440482 24809 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:57.473443 24679 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:57.476504 24821 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:16:57.476464 24818 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:16:57.476747 24819 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:16:57.476828 24679 server_base.cc:1061] running on GCE node
I20260812 06:16:57.477130 24679 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:57.477195 24679 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:16:57.477231 24679 hybrid_clock.cc:648] HybridClock initialized: now 1786515417477230 us; error 0 us; skew 500 ppm
I20260812 06:16:57.478184 24679 webserver.cc:533] Webserver started at http://127.24.25.193:39695/ using document root <none> and password file <none>
I20260812 06:16:57.478358 24679 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:57.478428 24679 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:57.478511 24679 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:57.478922 24679 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/instance:
uuid: "1e4eb7196223479d8a783b4a5afe88f9"
format_stamp: "Formatted at 2026-08-12 06:16:57 on dist-test-slave-gkw7"
I20260812 06:16:57.480499 24679 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:57.481577 24827 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:16:57.481878 24679 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:57.481966 24679 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root
uuid: "1e4eb7196223479d8a783b4a5afe88f9"
format_stamp: "Formatted at 2026-08-12 06:16:57 on dist-test-slave-gkw7"
I20260812 06:16:57.482050 24679 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-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:16:57.495849 24679 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:57.496558 24679 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:57.497080 24679 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:57.498003 24679 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:57.498085 24679 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:57.498163 24679 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:57.498209 24679 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:57.505147 24679 rpc_server.cc:307] RPC server started. Bound to: 127.24.25.193:45677
I20260812 06:16:57.505267 24927 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.25.193:45677 every 8 connection(s)
I20260812 06:16:57.515563 24928 heartbeater.cc:344] Connected to a master server at 127.24.25.254:38725
I20260812 06:16:57.515811 24928 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:57.516273 24928 heartbeater.cc:507] Master 127.24.25.254:38725 requested a full tablet report, sending...
I20260812 06:16:57.517889 24729 ts_manager.cc:194] Registered new tserver with Master: 1e4eb7196223479d8a783b4a5afe88f9 (127.24.25.193:45677)
I20260812 06:16:57.518573 24679 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012624418s
I20260812 06:16:57.519330 24729 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45880
I20260812 06:16:57.528914 24729 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45892:
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:16:57.544865 24869 tablet_service.cc:1511] Processing CreateTablet for tablet ff8e70d1bb824e2b9059c0d7f38a8b76 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bcbe5683053b46efa21eea7dc8d2ccd4]), partition=
I20260812 06:16:57.545446 24869 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ff8e70d1bb824e2b9059c0d7f38a8b76. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:57.548471 24946 tablet_bootstrap.cc:492] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Bootstrap starting.
I20260812 06:16:57.549819 24946 tablet_bootstrap.cc:654] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:57.551401 24946 tablet_bootstrap.cc:492] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: No bootstrap required, opened a new log
I20260812 06:16:57.551499 24946 ts_tablet_manager.cc:1403] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:57.552058 24946 raft_consensus.cc:359] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1e4eb7196223479d8a783b4a5afe88f9" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 45677 } }
I20260812 06:16:57.552171 24946 raft_consensus.cc:385] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:57.552198 24946 raft_consensus.cc:740] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1e4eb7196223479d8a783b4a5afe88f9, State: Initialized, Role: FOLLOWER
I20260812 06:16:57.552389 24946 consensus_queue.cc:260] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [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: "1e4eb7196223479d8a783b4a5afe88f9" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 45677 } }
I20260812 06:16:57.552487 24946 raft_consensus.cc:399] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:57.552599 24946 raft_consensus.cc:493] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:57.552716 24946 raft_consensus.cc:3060] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:57.553738 24946 raft_consensus.cc:515] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1e4eb7196223479d8a783b4a5afe88f9" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 45677 } }
I20260812 06:16:57.553907 24946 leader_election.cc:304] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [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: 1e4eb7196223479d8a783b4a5afe88f9; no voters: 
I20260812 06:16:57.554160 24946 leader_election.cc:290] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:57.554276 24948 raft_consensus.cc:2804] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:57.554512 24948 raft_consensus.cc:697] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 1 LEADER]: Becoming Leader. State: Replica: 1e4eb7196223479d8a783b4a5afe88f9, State: Running, Role: LEADER
I20260812 06:16:57.554598 24946 ts_tablet_manager.cc:1434] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:16:57.554754 24948 consensus_queue.cc:237] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [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: "1e4eb7196223479d8a783b4a5afe88f9" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 45677 } }
I20260812 06:16:57.554956 24928 heartbeater.cc:499] Master 127.24.25.254:38725 was elected leader, sending a full tablet report...
I20260812 06:16:57.558063 24729 catalog_manager.cc:5719] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1e4eb7196223479d8a783b4a5afe88f9 (127.24.25.193). New cstate: current_term: 1 leader_uuid: "1e4eb7196223479d8a783b4a5afe88f9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1e4eb7196223479d8a783b4a5afe88f9" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 45677 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:57.623713 24679 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.016s	sys 0.008s
I20260812 06:16:57.756392 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushMRSOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=19.054940
I20260812 06:16:57.935410 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushMRSOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.179s	user 0.134s	sys 0.041s Metrics: {"bytes_written":12717727,"cfile_init":1,"compiler_manager_pool.queue_time_us":199,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":800,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46330,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":125,"threads_started":1,"update_count":1550}
I20260812 06:16:57.936764 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling LogGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76): free 20743880 bytes of WAL
I20260812 06:16:57.937225 24834 log_reader.cc:385] T ff8e70d1bb824e2b9059c0d7f38a8b76: removed 2 log segments from log reader
I20260812 06:16:57.937361 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000001 (ops 1-6)
I20260812 06:16:57.937474 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000002 (ops 7-11)
I20260812 06:16:57.944259 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: LogGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:57.944725 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:57.975607 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.031s	user 0.012s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.976171 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling UndoDeltaBlockGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76): 16411392 bytes on disk
I20260812 06:16:57.976914 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: UndoDeltaBlockGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:16:57.977411 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:57.992578 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.015s	user 0.002s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5539,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:57.993268 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:16:58.185369 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.192s	user 0.148s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774790,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1082,"lbm_read_time_us":14488,"lbm_reads_lt_1ms":569,"lbm_write_time_us":32319,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"thread_start_us":356,"threads_started":5,"update_count":2500}
I20260812 06:16:58.185976 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:16:58.222671 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.036s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16045,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.223251 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:58.240222 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.017s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6694,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.240748 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:16:58.400447 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.160s	user 0.130s	sys 0.027s 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":896,"lbm_read_time_us":10722,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34496,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:58.401043 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:16:58.449921 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.049s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18830,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.450429 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:58.460901 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.461478 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:16:58.605798 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.144s	user 0.104s	sys 0.036s 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":513,"dirs.run_cpu_time_us":666,"dirs.run_wall_time_us":4163,"lbm_read_time_us":9837,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27919,"lbm_writes_lt_1ms":443,"mutex_wait_us":137,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:16:58.607031 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:16:58.644917 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.038s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16490,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.645401 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:58.658209 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4533,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.658704 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:16:58.781002 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.122s	user 0.100s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":97,"lbm_read_time_us":8304,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24970,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:58.781735 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:16:58.834741 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.053s	user 0.028s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20537,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.835287 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:58.860806 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.025s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.861270 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:58.871785 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.872270 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:16:59.056733 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.184s	user 0.117s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774806,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":197,"lbm_read_time_us":12848,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30979,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:16:59.057428 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=14.095187
I20260812 06:16:59.115211 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.058s	user 0.024s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19615,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.115801 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:59.127060 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4327,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.127508 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:16:59.317773 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.190s	user 0.125s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":13564,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30994,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:59.318465 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=14.095187
I20260812 06:16:59.380887 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.062s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24525,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.381453 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:59.398440 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6373,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.399058 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushMRSOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:16:59.439231 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushMRSOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.040s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1390,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1680,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:59.440222 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling LogGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76): free 132571327 bytes of WAL
I20260812 06:16:59.440495 24834 log_reader.cc:385] T ff8e70d1bb824e2b9059c0d7f38a8b76: removed 13 log segments from log reader
I20260812 06:16:59.440559 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000003 (ops 12-16)
I20260812 06:16:59.440621 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000004 (ops 17-21)
I20260812 06:16:59.440678 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000005 (ops 22-26)
I20260812 06:16:59.440727 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000006 (ops 27-31)
I20260812 06:16:59.440776 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000007 (ops 32-36)
I20260812 06:16:59.440820 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000008 (ops 37-41)
I20260812 06:16:59.440871 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000009 (ops 42-46)
I20260812 06:16:59.440940 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000010 (ops 47-51)
I20260812 06:16:59.440990 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000011 (ops 52-56)
I20260812 06:16:59.441045 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000012 (ops 57-60)
I20260812 06:16:59.441095 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000013 (ops 61-65)
I20260812 06:16:59.441144 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000014 (ops 66-70)
I20260812 06:16:59.441195 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000015 (ops 71-74)
I20260812 06:16:59.474149 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: LogGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.034s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:16:59.474689 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=3.181125
I20260812 06:16:59.491179 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4635981,"delete_count":0,"lbm_write_time_us":6291,"lbm_writes_lt_1ms":116,"reinsert_count":0,"update_count":565}
I20260812 06:16:59.491792 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling UndoDeltaBlockGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76): 493 bytes on disk
I20260812 06:16:59.492374 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: UndoDeltaBlockGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:16:59.492908 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:16:59.510715 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":6720,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:16:59.511373 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:16:59.745492 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.233s	user 0.149s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":614,"lbm_read_time_us":14370,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40557,"lbm_writes_lt_1ms":743,"mutex_wait_us":40,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:16:59.746284 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=14.095187
I20260812 06:16:59.793347 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.047s	user 0.018s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20148,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.793999 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:16:59.953665 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.159s	user 0.104s	sys 0.047s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1138,"lbm_read_time_us":10573,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25337,"lbm_writes_lt_1ms":443,"mutex_wait_us":341,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:16:59.954411 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=14.095187
I20260812 06:16:59.998411 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.044s	user 0.022s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19451,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.999046 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:00.132095 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.133s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":247,"lbm_read_time_us":8646,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23520,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":2000}
I20260812 06:17:00.132733 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:00.184540 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.052s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16435,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.185053 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:00.195529 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.195999 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:00.330363 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.134s	user 0.086s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":511,"lbm_read_time_us":10398,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25675,"lbm_writes_lt_1ms":443,"mutex_wait_us":121,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:17:00.331012 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:00.381304 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.050s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18176,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.381856 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:00.392856 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.393651 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:00.526072 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.132s	user 0.094s	sys 0.037s 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":1688,"lbm_read_time_us":10142,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26231,"lbm_writes_lt_1ms":443,"mutex_wait_us":380,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:17:00.526762 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:00.578915 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.052s	user 0.019s	sys 0.024s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15999,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.579535 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:00.590849 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.591332 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:00.754882 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.163s	user 0.107s	sys 0.051s 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":987,"lbm_read_time_us":11726,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26641,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:17:00.755456 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:00.794027 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.038s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14944,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.794592 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:00.913254 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.118s	user 0.078s	sys 0.041s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":179,"lbm_read_time_us":7010,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21867,"lbm_writes_lt_1ms":343,"mutex_wait_us":60,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":1500}
I20260812 06:17:00.914325 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:00.969722 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.055s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17852,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.970252 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:00.980736 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.981261 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushMRSOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:01.020459 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushMRSOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.039s	user 0.022s	sys 0.003s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1323,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1586,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:01.021245 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling LogGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76): free 121006462 bytes of WAL
I20260812 06:17:01.021493 24834 log_reader.cc:385] T ff8e70d1bb824e2b9059c0d7f38a8b76: removed 12 log segments from log reader
I20260812 06:17:01.021584 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000016 (ops 75-79)
I20260812 06:17:01.021651 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000017 (ops 80-84)
I20260812 06:17:01.021692 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000018 (ops 85-89)
I20260812 06:17:01.021734 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000019 (ops 90-94)
I20260812 06:17:01.021772 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000020 (ops 95-99)
I20260812 06:17:01.021826 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000021 (ops 100-104)
I20260812 06:17:01.021867 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000022 (ops 105-108)
I20260812 06:17:01.021908 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000023 (ops 109-113)
I20260812 06:17:01.021948 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000024 (ops 114-118)
I20260812 06:17:01.021988 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000025 (ops 119-123)
I20260812 06:17:01.022028 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000026 (ops 124-128)
I20260812 06:17:01.022068 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000027 (ops 129-133)
I20260812 06:17:01.050113 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: LogGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.029s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:17:01.050594 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling UndoDeltaBlockGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76): 462 bytes on disk
I20260812 06:17:01.051188 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: UndoDeltaBlockGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:01.051779 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=3.181125
I20260812 06:17:01.065371 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4730,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:01.065958 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:01.075735 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3653,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.076398 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:01.259378 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.183s	user 0.139s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":257,"lbm_read_time_us":12829,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37720,"lbm_writes_lt_1ms":643,"mutex_wait_us":90,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10624,"thread_start_us":108,"threads_started":1,"update_count":3000}
I20260812 06:17:01.262159 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=11.118625
I20260812 06:17:01.297012 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.035s	user 0.014s	sys 0.017s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14944,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.297839 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:01.311872 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5185,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.312367 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:01.439640 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.127s	user 0.105s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":535,"lbm_read_time_us":8245,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26363,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:01.440358 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=11.118625
I20260812 06:17:01.482472 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.042s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15299,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:01.483218 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:01.494133 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4161,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:01.494840 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:01.649682 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.155s	user 0.093s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1312,"lbm_read_time_us":12445,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25344,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2000}
I20260812 06:17:01.650430 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:01.699163 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.048s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16853,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.699692 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:01.711544 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4308,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.712291 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:01.845598 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.133s	user 0.110s	sys 0.023s 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":1432,"lbm_read_time_us":10031,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25011,"lbm_writes_lt_1ms":443,"mutex_wait_us":328,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:17:01.846396 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:01.894912 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.048s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15113,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.895504 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:01.911617 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.912417 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:02.068892 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.156s	user 0.130s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":267,"lbm_read_time_us":10409,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32217,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:02.069682 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:02.108355 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.038s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15837,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.108959 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:02.121615 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4504,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.122215 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:02.260475 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.138s	user 0.114s	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":600,"lbm_read_time_us":10028,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26034,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.261247 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:02.311532 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.050s	user 0.029s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19475,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.312273 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:02.330004 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.330536 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:02.477787 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.147s	user 0.096s	sys 0.049s 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":736,"lbm_read_time_us":11310,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25563,"lbm_writes_lt_1ms":443,"mutex_wait_us":340,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:02.480950 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:02.528173 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.047s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17153,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.528872 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=2.188937
I20260812 06:17:02.548571 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7655,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.549295 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushMRSOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:02.581504 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushMRSOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1334,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1999,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:02.582384 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling LogGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76): free 124257506 bytes of WAL
I20260812 06:17:02.582652 24834 log_reader.cc:385] T ff8e70d1bb824e2b9059c0d7f38a8b76: removed 12 log segments from log reader
I20260812 06:17:02.582721 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000028 (ops 134-138)
I20260812 06:17:02.582783 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000029 (ops 139-143)
I20260812 06:17:02.582835 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000030 (ops 144-148)
I20260812 06:17:02.582870 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000031 (ops 149-153)
I20260812 06:17:02.582932 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000032 (ops 154-158)
I20260812 06:17:02.582998 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000033 (ops 159-162)
I20260812 06:17:02.583052 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000034 (ops 163-167)
I20260812 06:17:02.583097 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000035 (ops 168-172)
I20260812 06:17:02.583140 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000036 (ops 173-177)
I20260812 06:17:02.583184 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000037 (ops 178-182)
I20260812 06:17:02.583228 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000038 (ops 183-187)
I20260812 06:17:02.583292 24834 log.cc:1079] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/ff8e70d1bb824e2b9059c0d7f38a8b76/wal-000000039 (ops 188-192)
I20260812 06:17:02.614008 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: LogGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.031s	user 0.002s	sys 0.029s Metrics: {}
I20260812 06:17:02.614565 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling UndoDeltaBlockGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76): 473 bytes on disk
I20260812 06:17:02.615139 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: UndoDeltaBlockGCOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.615856 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=3.181125
I20260812 06:17:02.646359 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.030s	user 0.014s	sys 0.015s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":8532,"lbm_writes_lt_1ms":131,"reinsert_count":0,"update_count":640}
I20260812 06:17:02.646998 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.196750
I20260812 06:17:02.656517 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3431,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:17:02.657143 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=1.000000
I20260812 06:17:02.803750 24679 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.180s	user 1.921s	sys 0.168s
I20260812 06:17:02.872484 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: MajorDeltaCompactionOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.215s	user 0.142s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15960,"lbm_reads_lt_1ms":670,"lbm_write_time_us":36688,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:17:02.873054 24931 maintenance_manager.cc:419] P 1e4eb7196223479d8a783b4a5afe88f9: Scheduling FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76): perf score=10.126437
I20260812 06:17:02.898764 24679 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.003s	sys 0.000s
I20260812 06:17:02.899583 24679 tablet_server.cc:179] TabletServer@127.24.25.193:0 shutting down...
I20260812 06:17:02.912395 24834 maintenance_manager.cc:643] P 1e4eb7196223479d8a783b4a5afe88f9: FlushDeltaMemStoresOp(ff8e70d1bb824e2b9059c0d7f38a8b76) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17050,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.913005 24679 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:02.913414 24679 tablet_replica.cc:333] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9: stopping tablet replica
I20260812 06:17:02.913684 24679 raft_consensus.cc:2243] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:02.913930 24679 raft_consensus.cc:2272] T ff8e70d1bb824e2b9059c0d7f38a8b76 P 1e4eb7196223479d8a783b4a5afe88f9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:02.928864 24679 tablet_server.cc:196] TabletServer@127.24.25.193:0 shutdown complete.
I20260812 06:17:02.934166 24679 master.cc:562] Master@127.24.25.254:38725 shutting down...
I20260812 06:17:02.938220 24679 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:02.938371 24679 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:02.938423 24679 tablet_replica.cc:333] T 00000000000000000000000000000000 P 28b114d7a0ba41dd991a351c7b3ce710: stopping tablet replica
I20260812 06:17:02.950686 24679 master.cc:584] Master@127.24.25.254:38725 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5740 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:03.058418 24679 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.25.254:44657
I20260812 06:17:03.058818 24679 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:03.060949 24679 server_base.cc:1061] running on GCE node
W20260812 06:17:03.061096 24981 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:03.061112 24984 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:03.061206 24980 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:03.061594 24679 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:03.061661 24679 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:03.061686 24679 hybrid_clock.cc:648] HybridClock initialized: now 1786515423061686 us; error 0 us; skew 500 ppm
I20260812 06:17:03.062551 24679 webserver.cc:533] Webserver started at http://127.24.25.254:34473/ using document root <none> and password file <none>
I20260812 06:17:03.062745 24679 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:03.062814 24679 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:03.062896 24679 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:03.063325 24679 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/master-0-root/instance:
uuid: "dfdf1686fde445bc8edeccb95ad42a9b"
format_stamp: "Formatted at 2026-08-12 06:17:03 on dist-test-slave-gkw7"
I20260812 06:17:03.064880 24679 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:03.065928 24994 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:03.066221 24679 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:03.066313 24679 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/master-0-root
uuid: "dfdf1686fde445bc8edeccb95ad42a9b"
format_stamp: "Formatted at 2026-08-12 06:17:03 on dist-test-slave-gkw7"
I20260812 06:17:03.066399 24679 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:03.081204 24679 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:03.081766 24679 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:03.086525 24679 rpc_server.cc:307] RPC server started. Bound to: 127.24.25.254:44657
I20260812 06:17:03.091382 25071 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:03.092433 25069 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.25.254:44657 every 8 connection(s)
I20260812 06:17:03.093827 25071 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b: Bootstrap starting.
I20260812 06:17:03.094643 25071 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:03.095768 25071 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b: No bootstrap required, opened a new log
I20260812 06:17:03.096235 25071 raft_consensus.cc:359] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfdf1686fde445bc8edeccb95ad42a9b" member_type: VOTER }
I20260812 06:17:03.096351 25071 raft_consensus.cc:385] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:03.096403 25071 raft_consensus.cc:740] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dfdf1686fde445bc8edeccb95ad42a9b, State: Initialized, Role: FOLLOWER
I20260812 06:17:03.096567 25071 consensus_queue.cc:260] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [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: "dfdf1686fde445bc8edeccb95ad42a9b" member_type: VOTER }
I20260812 06:17:03.096665 25071 raft_consensus.cc:399] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:03.096712 25071 raft_consensus.cc:493] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:03.096768 25071 raft_consensus.cc:3060] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:03.097481 25071 raft_consensus.cc:515] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfdf1686fde445bc8edeccb95ad42a9b" member_type: VOTER }
I20260812 06:17:03.097671 25071 leader_election.cc:304] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [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: dfdf1686fde445bc8edeccb95ad42a9b; no voters: 
I20260812 06:17:03.097882 25071 leader_election.cc:290] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:03.098179 25076 raft_consensus.cc:2804] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:03.098404 25076 raft_consensus.cc:697] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 1 LEADER]: Becoming Leader. State: Replica: dfdf1686fde445bc8edeccb95ad42a9b, State: Running, Role: LEADER
I20260812 06:17:03.098438 25071 sys_catalog.cc:565] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:03.098553 25076 consensus_queue.cc:237] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [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: "dfdf1686fde445bc8edeccb95ad42a9b" member_type: VOTER }
I20260812 06:17:03.099020 25079 sys_catalog.cc:455] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [sys.catalog]: SysCatalogTable state changed. Reason: New leader dfdf1686fde445bc8edeccb95ad42a9b. Latest consensus state: current_term: 1 leader_uuid: "dfdf1686fde445bc8edeccb95ad42a9b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfdf1686fde445bc8edeccb95ad42a9b" member_type: VOTER } }
I20260812 06:17:03.099009 25078 sys_catalog.cc:455] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "dfdf1686fde445bc8edeccb95ad42a9b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfdf1686fde445bc8edeccb95ad42a9b" member_type: VOTER } }
I20260812 06:17:03.099130 25078 sys_catalog.cc:458] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:03.099129 25079 sys_catalog.cc:458] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:03.099404 25086 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:03.100150 25086 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:03.100384 24679 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:03.102054 25086 catalog_manager.cc:1383] Generated new cluster ID: 09d9e4d968c444f484874c7c0ea65624
I20260812 06:17:03.102111 25086 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:03.117923 25086 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:03.118633 25086 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:03.126227 25086 catalog_manager.cc:6092] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b: Generated new TSK 0
I20260812 06:17:03.126479 25086 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:03.132846 24679 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:03.135181 24679 server_base.cc:1061] running on GCE node
W20260812 06:17:03.135146 25109 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:03.135159 25111 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:03.135293 25108 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:03.135603 24679 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:03.135651 24679 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:03.135668 24679 hybrid_clock.cc:648] HybridClock initialized: now 1786515423135668 us; error 0 us; skew 500 ppm
I20260812 06:17:03.136531 24679 webserver.cc:533] Webserver started at http://127.24.25.193:43997/ using document root <none> and password file <none>
I20260812 06:17:03.136730 24679 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:03.136801 24679 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:03.136911 24679 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:03.137387 24679 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/instance:
uuid: "5b6d853c94914efc955bb18ff0dc26bd"
format_stamp: "Formatted at 2026-08-12 06:17:03 on dist-test-slave-gkw7"
I20260812 06:17:03.138993 24679 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:03.140041 25117 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:03.140327 24679 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:03.140420 24679 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root
uuid: "5b6d853c94914efc955bb18ff0dc26bd"
format_stamp: "Formatted at 2026-08-12 06:17:03 on dist-test-slave-gkw7"
I20260812 06:17:03.140507 24679 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:03.154047 24679 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:03.154471 24679 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:03.154805 24679 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:03.155295 24679 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:03.155356 24679 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:03.155434 24679 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:03.155485 24679 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:03.159806 24679 rpc_server.cc:307] RPC server started. Bound to: 127.24.25.193:37687
I20260812 06:17:03.161319 25226 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.25.193:37687 every 8 connection(s)
I20260812 06:17:03.169255 25228 heartbeater.cc:344] Connected to a master server at 127.24.25.254:44657
I20260812 06:17:03.169389 25228 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:03.169725 25228 heartbeater.cc:507] Master 127.24.25.254:44657 requested a full tablet report, sending...
I20260812 06:17:03.170437 25016 ts_manager.cc:194] Registered new tserver with Master: 5b6d853c94914efc955bb18ff0dc26bd (127.24.25.193:37687)
I20260812 06:17:03.170784 24679 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009990195s
I20260812 06:17:03.171231 25016 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44400
I20260812 06:17:03.178018 25016 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44412:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:03.188045 25155 tablet_service.cc:1511] Processing CreateTablet for tablet cbe12475cf6c46ebbd3c40d8d175e583 (DEFAULT_TABLE table=heavy-update-compaction-test [id=41b2eb72fd5642199223e690fcb6c3ef]), partition=
I20260812 06:17:03.188370 25155 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cbe12475cf6c46ebbd3c40d8d175e583. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:03.190730 25241 tablet_bootstrap.cc:492] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Bootstrap starting.
I20260812 06:17:03.191761 25241 tablet_bootstrap.cc:654] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:03.193084 25241 tablet_bootstrap.cc:492] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: No bootstrap required, opened a new log
I20260812 06:17:03.193199 25241 ts_tablet_manager.cc:1403] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:03.193783 25241 raft_consensus.cc:359] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b6d853c94914efc955bb18ff0dc26bd" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 37687 } }
I20260812 06:17:03.193878 25241 raft_consensus.cc:385] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:03.193902 25241 raft_consensus.cc:740] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5b6d853c94914efc955bb18ff0dc26bd, State: Initialized, Role: FOLLOWER
I20260812 06:17:03.193997 25241 consensus_queue.cc:260] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [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: "5b6d853c94914efc955bb18ff0dc26bd" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 37687 } }
I20260812 06:17:03.194057 25241 raft_consensus.cc:399] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:03.194080 25241 raft_consensus.cc:493] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:03.194108 25241 raft_consensus.cc:3060] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:03.194869 25241 raft_consensus.cc:515] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b6d853c94914efc955bb18ff0dc26bd" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 37687 } }
I20260812 06:17:03.194998 25241 leader_election.cc:304] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [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: 5b6d853c94914efc955bb18ff0dc26bd; no voters: 
I20260812 06:17:03.195164 25241 leader_election.cc:290] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:03.195329 25243 raft_consensus.cc:2804] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:03.195583 25243 raft_consensus.cc:697] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 1 LEADER]: Becoming Leader. State: Replica: 5b6d853c94914efc955bb18ff0dc26bd, State: Running, Role: LEADER
I20260812 06:17:03.195569 25228 heartbeater.cc:499] Master 127.24.25.254:44657 was elected leader, sending a full tablet report...
I20260812 06:17:03.195571 25241 ts_tablet_manager.cc:1434] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:03.195760 25243 consensus_queue.cc:237] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [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: "5b6d853c94914efc955bb18ff0dc26bd" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 37687 } }
I20260812 06:17:03.197136 25016 catalog_manager.cc:5719] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd reported cstate change: term changed from 0 to 1, leader changed from <none> to 5b6d853c94914efc955bb18ff0dc26bd (127.24.25.193). New cstate: current_term: 1 leader_uuid: "5b6d853c94914efc955bb18ff0dc26bd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b6d853c94914efc955bb18ff0dc26bd" member_type: VOTER last_known_addr { host: "127.24.25.193" port: 37687 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:03.257701 24679 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.009s	sys 0.014s
I20260812 06:17:03.411760 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushMRSOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=19.054940
I20260812 06:17:03.587347 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushMRSOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.175s	user 0.125s	sys 0.048s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":739,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45709,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:03.588081 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling LogGCOp(cbe12475cf6c46ebbd3c40d8d175e583): free 20743831 bytes of WAL
I20260812 06:17:03.588351 25125 log_reader.cc:385] T cbe12475cf6c46ebbd3c40d8d175e583: removed 2 log segments from log reader
I20260812 06:17:03.588402 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000001 (ops 1-6)
I20260812 06:17:03.588433 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000002 (ops 7-11)
I20260812 06:17:03.592986 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: LogGCOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:03.593374 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:03.606719 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.607326 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling UndoDeltaBlockGCOp(cbe12475cf6c46ebbd3c40d8d175e583): 16411393 bytes on disk
I20260812 06:17:03.607795 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: UndoDeltaBlockGCOp(cbe12475cf6c46ebbd3c40d8d175e583) 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:17:03.608287 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:03.769702 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.161s	user 0.117s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":433,"lbm_read_time_us":11598,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26794,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":382,"threads_started":5,"update_count":2000}
I20260812 06:17:03.770285 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=11.118625
I20260812 06:17:03.818311 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.048s	user 0.020s	sys 0.027s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15909,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:03.818883 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:03.830130 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:03.830569 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:03.985270 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.155s	user 0.104s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":552,"lbm_read_time_us":12341,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23498,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":2000}
I20260812 06:17:03.985898 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=11.118625
I20260812 06:17:04.024331 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.038s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16387,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:04.024893 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:04.043867 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.019s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":450}
I20260812 06:17:04.044327 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:04.054697 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.055406 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:04.228857 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.173s	user 0.151s	sys 0.015s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":289,"lbm_read_time_us":12969,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30243,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:04.229574 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=11.118625
I20260812 06:17:04.270092 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.040s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17657,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:04.270864 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:04.288679 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.018s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4115,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.289274 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:04.423821 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.134s	user 0.100s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":378,"lbm_read_time_us":8373,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25214,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:04.424448 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=11.118625
I20260812 06:17:04.462503 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12717741,"delete_count":0,"lbm_write_time_us":17372,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:04.463438 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:04.479681 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5565,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.480314 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:04.632972 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.152s	user 0.103s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672274,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":284,"lbm_read_time_us":9025,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27853,"lbm_writes_lt_1ms":443,"mutex_wait_us":81,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:17:04.633852 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=14.095187
I20260812 06:17:04.691105 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.057s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19395,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.691689 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:04.703785 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.704504 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:04.882161 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.177s	user 0.112s	sys 0.063s 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":130,"lbm_read_time_us":12572,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29724,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":66688,"update_count":2500}
I20260812 06:17:04.882900 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=14.095187
I20260812 06:17:04.945014 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.062s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20209,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.945691 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:04.957098 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.957628 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushMRSOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:05.007632 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushMRSOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.050s	user 0.031s	sys 0.005s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1338,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1523,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":2304}
I20260812 06:17:05.008461 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling LogGCOp(cbe12475cf6c46ebbd3c40d8d175e583): free 121006482 bytes of WAL
I20260812 06:17:05.008800 25125 log_reader.cc:385] T cbe12475cf6c46ebbd3c40d8d175e583: removed 12 log segments from log reader
I20260812 06:17:05.008862 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000003 (ops 12-16)
I20260812 06:17:05.008924 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000004 (ops 17-21)
I20260812 06:17:05.008987 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000005 (ops 22-26)
I20260812 06:17:05.009073 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000006 (ops 27-31)
I20260812 06:17:05.009143 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000007 (ops 32-36)
I20260812 06:17:05.009217 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000008 (ops 37-41)
I20260812 06:17:05.009267 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000009 (ops 42-46)
I20260812 06:17:05.009317 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000010 (ops 47-51)
I20260812 06:17:05.009368 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000011 (ops 52-56)
I20260812 06:17:05.009416 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000012 (ops 57-60)
I20260812 06:17:05.009464 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000013 (ops 61-65)
I20260812 06:17:05.009512 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000014 (ops 66-70)
I20260812 06:17:05.040230 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: LogGCOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.032s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:17:05.040907 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling UndoDeltaBlockGCOp(cbe12475cf6c46ebbd3c40d8d175e583): 482 bytes on disk
I20260812 06:17:05.041579 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: UndoDeltaBlockGCOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:17:05.042397 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=4.173312
I20260812 06:17:05.063982 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.021s	user 0.009s	sys 0.011s Metrics: {"bytes_written":5948753,"delete_count":0,"lbm_write_time_us":8943,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:17:05.064499 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.196750
I20260812 06:17:05.073438 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.009s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2256529,"delete_count":0,"lbm_write_time_us":2454,"lbm_writes_lt_1ms":58,"reinsert_count":0,"update_count":275}
I20260812 06:17:05.074122 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:05.299746 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.225s	user 0.163s	sys 0.055s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979708,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":138,"lbm_read_time_us":14913,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39669,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8320,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:17:05.300501 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=18.063937
I20260812 06:17:05.369006 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.068s	user 0.035s	sys 0.028s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":29696,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:05.369520 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:05.385368 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5905,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.385978 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:05.589632 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.203s	user 0.143s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2091,"lbm_read_time_us":18129,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32673,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:17:05.590394 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=14.095187
I20260812 06:17:05.636474 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19782,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:05.637171 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:05.666723 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.029s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.667183 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:05.678256 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4203,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.678788 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:05.849351 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.170s	user 0.108s	sys 0.059s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":306,"lbm_read_time_us":12762,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35459,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":3000}
I20260812 06:17:05.849998 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=14.095187
I20260812 06:17:05.899966 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.050s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21938,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:05.900538 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:05.917130 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.917708 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:06.080993 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.163s	user 0.122s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":705,"lbm_read_time_us":9759,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29314,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:06.081698 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=14.095187
I20260812 06:17:06.131657 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.050s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21063,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.132457 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:06.287134 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.154s	user 0.116s	sys 0.034s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":401,"lbm_read_time_us":10638,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26132,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:06.288004 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=14.095187
I20260812 06:17:06.336112 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.048s	user 0.023s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23112,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.336591 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:06.349007 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4161,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.349668 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushMRSOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:06.388367 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushMRSOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.038s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":1370,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1991,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:06.389143 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling LogGCOp(cbe12475cf6c46ebbd3c40d8d175e583): free 124257253 bytes of WAL
I20260812 06:17:06.389417 25125 log_reader.cc:385] T cbe12475cf6c46ebbd3c40d8d175e583: removed 12 log segments from log reader
I20260812 06:17:06.389484 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000015 (ops 71-75)
I20260812 06:17:06.389536 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000016 (ops 76-80)
I20260812 06:17:06.389611 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000017 (ops 81-85)
I20260812 06:17:06.389649 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000018 (ops 86-90)
I20260812 06:17:06.389688 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000019 (ops 91-95)
I20260812 06:17:06.389727 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000020 (ops 96-100)
I20260812 06:17:06.389767 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000021 (ops 101-105)
I20260812 06:17:06.389806 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000022 (ops 106-110)
I20260812 06:17:06.389845 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000023 (ops 111-114)
I20260812 06:17:06.389885 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000024 (ops 115-119)
I20260812 06:17:06.389925 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000025 (ops 120-124)
I20260812 06:17:06.389962 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000026 (ops 125-129)
I20260812 06:17:06.419386 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: LogGCOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.030s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:17:06.419850 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling UndoDeltaBlockGCOp(cbe12475cf6c46ebbd3c40d8d175e583): 447 bytes on disk
I20260812 06:17:06.420569 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: UndoDeltaBlockGCOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:06.421129 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=3.181125
I20260812 06:17:06.442750 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.021s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":7504,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:06.443173 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:06.452597 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3617,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:06.453012 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:06.700068 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.247s	user 0.183s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":998,"lbm_read_time_us":17624,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39907,"lbm_writes_lt_1ms":743,"mutex_wait_us":72,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7552,"thread_start_us":122,"threads_started":1,"update_count":3500}
I20260812 06:17:06.701093 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=16.079562
I20260812 06:17:06.752090 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.051s	user 0.032s	sys 0.015s Metrics: {"bytes_written":17558578,"delete_count":0,"lbm_write_time_us":21836,"lbm_writes_lt_1ms":431,"reinsert_count":0,"update_count":2140}
I20260812 06:17:06.752853 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.196750
I20260812 06:17:06.772646 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.020s	user 0.000s	sys 0.011s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":4684,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:17:06.773113 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:06.784266 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.784785 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:06.994134 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.209s	user 0.126s	sys 0.083s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877192,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":177,"lbm_read_time_us":13780,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35565,"lbm_writes_lt_1ms":643,"mutex_wait_us":69,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":3000}
I20260812 06:17:06.994726 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=14.095187
I20260812 06:17:07.034687 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.040s	user 0.039s	sys 0.000s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":18087,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.035234 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:07.046275 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.046733 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:07.229348 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.182s	user 0.138s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774694,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":13279,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31460,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2500}
I20260812 06:17:07.230259 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=11.118625
I20260812 06:17:07.281461 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.051s	user 0.026s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16948,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.282382 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:07.297451 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.015s	user 0.000s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5773,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.298069 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:07.456926 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.159s	user 0.106s	sys 0.052s 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":166,"lbm_read_time_us":11237,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25810,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23424,"update_count":2000}
I20260812 06:17:07.457753 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=10.126437
I20260812 06:17:07.498437 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17805,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.499151 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:07.515381 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.516023 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:07.642441 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.126s	user 0.102s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":691,"lbm_read_time_us":8561,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26206,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32128,"update_count":2000}
I20260812 06:17:07.642949 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=10.126437
I20260812 06:17:07.691107 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.048s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14887,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.691694 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:07.704679 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4795,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.705240 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:07.843309 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.138s	user 0.102s	sys 0.036s 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":306,"lbm_read_time_us":10907,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27855,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2000}
I20260812 06:17:07.844074 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=10.126437
I20260812 06:17:07.891829 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.048s	user 0.018s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15544,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.892477 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:07.905252 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.905779 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushMRSOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:07.949494 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushMRSOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.044s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1423,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2162,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:07.950349 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling LogGCOp(cbe12475cf6c46ebbd3c40d8d175e583): free 112239510 bytes of WAL
I20260812 06:17:07.950604 25125 log_reader.cc:385] T cbe12475cf6c46ebbd3c40d8d175e583: removed 11 log segments from log reader
I20260812 06:17:07.950654 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000027 (ops 130-134)
I20260812 06:17:07.950685 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000028 (ops 135-139)
I20260812 06:17:07.950752 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000029 (ops 140-144)
I20260812 06:17:07.950820 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000030 (ops 145-149)
I20260812 06:17:07.950887 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000031 (ops 150-154)
I20260812 06:17:07.950934 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000032 (ops 155-159)
I20260812 06:17:07.950994 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000033 (ops 160-164)
I20260812 06:17:07.951036 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000034 (ops 165-168)
I20260812 06:17:07.951088 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000035 (ops 169-173)
I20260812 06:17:07.951131 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000036 (ops 174-178)
I20260812 06:17:07.951184 25125 log.cc:1079] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: Deleting log segment in path: /tmp/dist-test-tasktVOmnA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515417294016-24679-0/minicluster-data/ts-0-root/wals/cbe12475cf6c46ebbd3c40d8d175e583/wal-000000037 (ops 179-183)
I20260812 06:17:07.979914 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: LogGCOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:07.980475 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=3.181125
I20260812 06:17:08.006232 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.025s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5149,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:08.006835 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling UndoDeltaBlockGCOp(cbe12475cf6c46ebbd3c40d8d175e583): 463 bytes on disk
I20260812 06:17:08.007321 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: UndoDeltaBlockGCOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:08.007958 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:08.018013 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:08.018877 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:08.226868 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.208s	user 0.124s	sys 0.083s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":193,"lbm_read_time_us":13977,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35662,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":105,"threads_started":1,"update_count":3000}
I20260812 06:17:08.227710 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=15.087375
I20260812 06:17:08.280117 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.052s	user 0.018s	sys 0.032s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23177,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:08.280738 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=2.188937
I20260812 06:17:08.294202 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: FlushDeltaMemStoresOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4804,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:08.294782 25229 maintenance_manager.cc:419] P 5b6d853c94914efc955bb18ff0dc26bd: Scheduling MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583): perf score=1.000000
I20260812 06:17:08.323661 24679 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.066s	user 1.835s	sys 0.144s
I20260812 06:17:08.391265 24679 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.001s	sys 0.000s
I20260812 06:17:08.391821 24679 tablet_server.cc:179] TabletServer@127.24.25.193:0 shutting down...
I20260812 06:17:08.449302 25125 maintenance_manager.cc:643] P 5b6d853c94914efc955bb18ff0dc26bd: MajorDeltaCompactionOp(cbe12475cf6c46ebbd3c40d8d175e583) complete. Timing: real 0.154s	user 0.110s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":340,"lbm_read_time_us":13137,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25679,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:17:08.449941 24679 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:08.450219 24679 tablet_replica.cc:333] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd: stopping tablet replica
I20260812 06:17:08.450358 24679 raft_consensus.cc:2243] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:08.450554 24679 raft_consensus.cc:2272] T cbe12475cf6c46ebbd3c40d8d175e583 P 5b6d853c94914efc955bb18ff0dc26bd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:08.455816 24679 tablet_server.cc:196] TabletServer@127.24.25.193:0 shutdown complete.
I20260812 06:17:08.495752 24679 master.cc:562] Master@127.24.25.254:44657 shutting down...
I20260812 06:17:08.499418 24679 raft_consensus.cc:2243] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:08.499598 24679 raft_consensus.cc:2272] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:08.499650 24679 tablet_replica.cc:333] T 00000000000000000000000000000000 P dfdf1686fde445bc8edeccb95ad42a9b: stopping tablet replica
I20260812 06:17:08.512140 24679 master.cc:584] Master@127.24.25.254:44657 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5562 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11304 ms total)

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