[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:10.136658 25582 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.251.190:35963
I20260812 06:17:10.137746 25582 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:10.138312 25582 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:10.144779 25591 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:10.144876 25596 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:10.144865 25590 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:10.145279 25582 server_base.cc:1061] running on GCE node
I20260812 06:17:10.145794 25582 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.145936 25582 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:10.146003 25582 hybrid_clock.cc:648] HybridClock initialized: now 1786515430145999 us; error 0 us; skew 500 ppm
I20260812 06:17:10.147857 25582 webserver.cc:533] Webserver started at http://127.24.251.190:43761/ using document root <none> and password file <none>
I20260812 06:17:10.148445 25582 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.148537 25582 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.148803 25582 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.150537 25582 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/master-0-root/instance:
uuid: "79b888a7c6914d78934b113d85d97e4f"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-9gcw"
I20260812 06:17:10.154187 25582 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:17:10.156316 25602 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:10.157472 25582 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:10.157610 25582 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/master-0-root
uuid: "79b888a7c6914d78934b113d85d97e4f"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-9gcw"
I20260812 06:17:10.157722 25582 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-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:10.180533 25582 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.181304 25582 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:10.181514 25582 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.189949 25582 rpc_server.cc:307] RPC server started. Bound to: 127.24.251.190:35963
I20260812 06:17:10.189975 25667 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.251.190:35963 every 8 connection(s)
I20260812 06:17:10.192348 25668 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:10.197992 25668 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f: Bootstrap starting.
I20260812 06:17:10.200423 25668 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.201426 25668 log.cc:826] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:10.203510 25668 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f: No bootstrap required, opened a new log
I20260812 06:17:10.206557 25668 raft_consensus.cc:359] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79b888a7c6914d78934b113d85d97e4f" member_type: VOTER }
I20260812 06:17:10.206786 25668 raft_consensus.cc:385] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.206887 25668 raft_consensus.cc:740] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 79b888a7c6914d78934b113d85d97e4f, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.207515 25668 consensus_queue.cc:260] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [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: "79b888a7c6914d78934b113d85d97e4f" member_type: VOTER }
I20260812 06:17:10.207691 25668 raft_consensus.cc:399] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.207790 25668 raft_consensus.cc:493] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.207948 25668 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.208808 25668 raft_consensus.cc:515] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79b888a7c6914d78934b113d85d97e4f" member_type: VOTER }
I20260812 06:17:10.209281 25668 leader_election.cc:304] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [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: 79b888a7c6914d78934b113d85d97e4f; no voters: 
I20260812 06:17:10.209621 25668 leader_election.cc:290] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.209775 25672 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.210074 25672 raft_consensus.cc:697] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 1 LEADER]: Becoming Leader. State: Replica: 79b888a7c6914d78934b113d85d97e4f, State: Running, Role: LEADER
I20260812 06:17:10.210507 25672 consensus_queue.cc:237] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [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: "79b888a7c6914d78934b113d85d97e4f" member_type: VOTER }
I20260812 06:17:10.210716 25668 sys_catalog.cc:565] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:10.212602 25675 sys_catalog.cc:455] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "79b888a7c6914d78934b113d85d97e4f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79b888a7c6914d78934b113d85d97e4f" member_type: VOTER } }
I20260812 06:17:10.212759 25675 sys_catalog.cc:458] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.212625 25676 sys_catalog.cc:455] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 79b888a7c6914d78934b113d85d97e4f. Latest consensus state: current_term: 1 leader_uuid: "79b888a7c6914d78934b113d85d97e4f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79b888a7c6914d78934b113d85d97e4f" member_type: VOTER } }
I20260812 06:17:10.213065 25676 sys_catalog.cc:458] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.213127 25582 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:10.213116 25690 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:10.215456 25690 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:10.219892 25690 catalog_manager.cc:1383] Generated new cluster ID: 013fd29685bb4d4e8af272bb008a28c1
I20260812 06:17:10.219967 25690 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:10.231781 25690 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:10.232661 25690 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:10.245636 25690 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f: Generated new TSK 0
I20260812 06:17:10.246347 25690 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:10.278122 25582 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:10.281226 25582 server_base.cc:1061] running on GCE node
W20260812 06:17:10.281226 25696 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:10.281358 25701 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:10.281560 25698 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:10.281786 25582 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.281860 25582 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:10.281888 25582 hybrid_clock.cc:648] HybridClock initialized: now 1786515430281886 us; error 0 us; skew 500 ppm
I20260812 06:17:10.282881 25582 webserver.cc:533] Webserver started at http://127.24.251.129:41189/ using document root <none> and password file <none>
I20260812 06:17:10.283067 25582 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.283141 25582 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.283224 25582 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.283653 25582 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/instance:
uuid: "92d04c1d7a044025bdc7ad968eb0c801"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-9gcw"
I20260812 06:17:10.285279 25582 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:17:10.286345 25706 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:10.286612 25582 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:10.286685 25582 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root
uuid: "92d04c1d7a044025bdc7ad968eb0c801"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-9gcw"
I20260812 06:17:10.286784 25582 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-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:10.302963 25582 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.303728 25582 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.304291 25582 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:10.305300 25582 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:10.305358 25582 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.305425 25582 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:10.305466 25582 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.312172 25582 rpc_server.cc:307] RPC server started. Bound to: 127.24.251.129:43803
I20260812 06:17:10.312254 25780 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.251.129:43803 every 8 connection(s)
I20260812 06:17:10.322561 25781 heartbeater.cc:344] Connected to a master server at 127.24.251.190:35963
I20260812 06:17:10.322825 25781 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:10.323274 25781 heartbeater.cc:507] Master 127.24.251.190:35963 requested a full tablet report, sending...
I20260812 06:17:10.324782 25624 ts_manager.cc:194] Registered new tserver with Master: 92d04c1d7a044025bdc7ad968eb0c801 (127.24.251.129:43803)
I20260812 06:17:10.325631 25582 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012748555s
I20260812 06:17:10.326220 25624 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41000
I20260812 06:17:10.335675 25624 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41016:
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:10.350653 25738 tablet_service.cc:1511] Processing CreateTablet for tablet 394effd027c045918b157614f0269922 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5b5386f59b64452c992e24daf57a4a1b]), partition=
I20260812 06:17:10.351166 25738 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 394effd027c045918b157614f0269922. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:10.354164 25794 tablet_bootstrap.cc:492] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Bootstrap starting.
I20260812 06:17:10.355125 25794 tablet_bootstrap.cc:654] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.356654 25794 tablet_bootstrap.cc:492] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: No bootstrap required, opened a new log
I20260812 06:17:10.356791 25794 ts_tablet_manager.cc:1403] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:10.357471 25794 raft_consensus.cc:359] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "92d04c1d7a044025bdc7ad968eb0c801" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 43803 } }
I20260812 06:17:10.357597 25794 raft_consensus.cc:385] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.357650 25794 raft_consensus.cc:740] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 92d04c1d7a044025bdc7ad968eb0c801, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.357832 25794 consensus_queue.cc:260] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [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: "92d04c1d7a044025bdc7ad968eb0c801" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 43803 } }
I20260812 06:17:10.357941 25794 raft_consensus.cc:399] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.358014 25794 raft_consensus.cc:493] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.358072 25794 raft_consensus.cc:3060] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.358837 25794 raft_consensus.cc:515] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "92d04c1d7a044025bdc7ad968eb0c801" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 43803 } }
I20260812 06:17:10.358951 25794 leader_election.cc:304] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [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: 92d04c1d7a044025bdc7ad968eb0c801; no voters: 
I20260812 06:17:10.359239 25794 leader_election.cc:290] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.359352 25797 raft_consensus.cc:2804] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.359591 25797 raft_consensus.cc:697] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 1 LEADER]: Becoming Leader. State: Replica: 92d04c1d7a044025bdc7ad968eb0c801, State: Running, Role: LEADER
I20260812 06:17:10.359630 25794 ts_tablet_manager.cc:1434] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:10.359786 25797 consensus_queue.cc:237] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [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: "92d04c1d7a044025bdc7ad968eb0c801" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 43803 } }
I20260812 06:17:10.359802 25781 heartbeater.cc:499] Master 127.24.251.190:35963 was elected leader, sending a full tablet report...
I20260812 06:17:10.362730 25624 catalog_manager.cc:5719] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 reported cstate change: term changed from 0 to 1, leader changed from <none> to 92d04c1d7a044025bdc7ad968eb0c801 (127.24.251.129). New cstate: current_term: 1 leader_uuid: "92d04c1d7a044025bdc7ad968eb0c801" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "92d04c1d7a044025bdc7ad968eb0c801" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 43803 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:10.432166 25582 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.023s	sys 0.009s
I20260812 06:17:10.563441 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushMRSOp(394effd027c045918b157614f0269922): perf score=19.054940
I20260812 06:17:10.752611 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushMRSOp(394effd027c045918b157614f0269922) complete. Timing: real 0.189s	user 0.141s	sys 0.032s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":238,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1089,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44688,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":158,"threads_started":1,"update_count":1500}
I20260812 06:17:10.753975 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling LogGCOp(394effd027c045918b157614f0269922): free 20743880 bytes of WAL
I20260812 06:17:10.754307 25712 log_reader.cc:385] T 394effd027c045918b157614f0269922: removed 2 log segments from log reader
I20260812 06:17:10.754375 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000001 (ops 1-6)
I20260812 06:17:10.754441 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000002 (ops 7-11)
I20260812 06:17:10.759817 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: LogGCOp(394effd027c045918b157614f0269922) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:10.760272 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling UndoDeltaBlockGCOp(394effd027c045918b157614f0269922): 16411392 bytes on disk
I20260812 06:17:10.760942 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: UndoDeltaBlockGCOp(394effd027c045918b157614f0269922) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.761457 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:10.795233 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.034s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6309,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.795797 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:10.806775 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.807350 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:10.979168 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.172s	user 0.126s	sys 0.046s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":610,"lbm_read_time_us":11938,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30112,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":374,"threads_started":5,"update_count":2500}
I20260812 06:17:10.979831 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=10.126437
I20260812 06:17:11.030174 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.050s	user 0.035s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17422,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.030757 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:11.043386 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4628,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.043905 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:11.176555 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.132s	user 0.101s	sys 0.030s 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":8483,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26194,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30976,"update_count":2000}
I20260812 06:17:11.177188 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=10.126437
I20260812 06:17:11.220718 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.043s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14118,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.221236 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:11.232906 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.233562 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:11.371752 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.138s	user 0.110s	sys 0.028s 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":297,"lbm_read_time_us":9847,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27686,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2000}
I20260812 06:17:11.372413 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=10.126437
I20260812 06:17:11.419205 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.047s	user 0.011s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15249,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.419709 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:11.431501 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.431989 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:11.558286 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.126s	user 0.106s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":7751,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25179,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:17:11.559067 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=10.126437
I20260812 06:17:11.611248 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.052s	user 0.035s	sys 0.014s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20523,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.611927 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:11.623019 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.623514 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:11.771358 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.148s	user 0.117s	sys 0.028s 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":353,"lbm_read_time_us":10654,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22932,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:17:11.772168 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=10.126437
I20260812 06:17:11.813971 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.042s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16517,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.814458 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:11.826274 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4346,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.826849 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:11.954361 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.127s	user 0.099s	sys 0.028s 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":731,"lbm_read_time_us":7884,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25655,"lbm_writes_lt_1ms":443,"mutex_wait_us":338,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2000}
I20260812 06:17:11.955154 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=10.126437
I20260812 06:17:11.995217 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.040s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16006,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.995831 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:12.015269 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.019s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5789,"lbm_writes_lt_1ms":103,"mutex_wait_us":30,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.015878 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushMRSOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:12.067111 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushMRSOp(394effd027c045918b157614f0269922) complete. Timing: real 0.051s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":296,"dirs.run_wall_time_us":1536,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1552,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:12.067965 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling LogGCOp(394effd027c045918b157614f0269922): free 120553374 bytes of WAL
I20260812 06:17:12.068193 25712 log_reader.cc:385] T 394effd027c045918b157614f0269922: removed 12 log segments from log reader
I20260812 06:17:12.068254 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000003 (ops 12-16)
I20260812 06:17:12.068310 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000004 (ops 17-20)
I20260812 06:17:12.068368 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000005 (ops 21-25)
I20260812 06:17:12.068410 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000006 (ops 26-30)
I20260812 06:17:12.068445 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000007 (ops 31-35)
I20260812 06:17:12.068485 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000008 (ops 36-40)
I20260812 06:17:12.068521 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000009 (ops 41-45)
I20260812 06:17:12.068558 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000010 (ops 46-50)
I20260812 06:17:12.068595 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000011 (ops 51-54)
I20260812 06:17:12.068631 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000012 (ops 55-59)
I20260812 06:17:12.068668 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000013 (ops 60-64)
I20260812 06:17:12.068704 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000014 (ops 65-69)
I20260812 06:17:12.094645 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: LogGCOp(394effd027c045918b157614f0269922) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:12.095119 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=7.149875
I20260812 06:17:12.118359 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.023s	user 0.005s	sys 0.017s Metrics: {"bytes_written":8615322,"delete_count":0,"lbm_write_time_us":9706,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:12.118979 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling UndoDeltaBlockGCOp(394effd027c045918b157614f0269922): 471 bytes on disk
I20260812 06:17:12.119516 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: UndoDeltaBlockGCOp(394effd027c045918b157614f0269922) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.120031 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:12.134433 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5648,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.135066 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:12.335947 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.201s	user 0.128s	sys 0.072s 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":2315,"lbm_read_time_us":14179,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40090,"lbm_writes_lt_1ms":743,"mutex_wait_us":609,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":117,"threads_started":1,"update_count":3500}
I20260812 06:17:12.336633 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:12.407529 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.071s	user 0.035s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26371,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.408078 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=3.181125
I20260812 06:17:12.421387 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4923145,"delete_count":0,"lbm_write_time_us":5549,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 06:17:12.421837 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:12.431124 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":3409,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:17:12.431587 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:12.634116 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.202s	user 0.162s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877200,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":638,"lbm_read_time_us":14878,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35693,"lbm_writes_lt_1ms":643,"mutex_wait_us":342,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":3000}
I20260812 06:17:12.634811 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:12.694937 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.060s	user 0.023s	sys 0.035s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":24553,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.695644 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:12.712100 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.712631 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:12.876412 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.164s	user 0.099s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":389,"lbm_read_time_us":10024,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28077,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":61312,"update_count":2500}
I20260812 06:17:12.876951 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:12.938663 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.062s	user 0.021s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21808,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.939262 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:12.950363 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.951138 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:13.170619 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.219s	user 0.152s	sys 0.065s 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":888,"lbm_read_time_us":13585,"lbm_reads_lt_1ms":572,"lbm_write_time_us":41965,"lbm_writes_lt_1ms":543,"mutex_wait_us":423,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:17:13.171280 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=11.118625
I20260812 06:17:13.223695 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.052s	user 0.027s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":22253,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:13.224741 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:13.250993 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.026s	user 0.011s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5117,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.251566 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:13.263296 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4584,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.263887 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:13.477011 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.213s	user 0.161s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":254,"lbm_read_time_us":12981,"lbm_reads_lt_1ms":573,"lbm_write_time_us":36518,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:17:13.477748 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:13.530467 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.052s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21786,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.530985 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:13.546372 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5753,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.546859 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushMRSOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:13.594878 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushMRSOp(394effd027c045918b157614f0269922) complete. Timing: real 0.048s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":1447,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2360,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:13.595808 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling LogGCOp(394effd027c045918b157614f0269922): free 112692379 bytes of WAL
I20260812 06:17:13.596130 25712 log_reader.cc:385] T 394effd027c045918b157614f0269922: removed 11 log segments from log reader
I20260812 06:17:13.596218 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000015 (ops 70-74)
I20260812 06:17:13.596261 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000016 (ops 75-79)
I20260812 06:17:13.596305 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000017 (ops 80-84)
I20260812 06:17:13.596364 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000018 (ops 85-89)
I20260812 06:17:13.596416 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000019 (ops 90-94)
I20260812 06:17:13.596441 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000020 (ops 95-99)
I20260812 06:17:13.596462 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000021 (ops 100-104)
I20260812 06:17:13.596494 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000022 (ops 105-109)
I20260812 06:17:13.596530 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000023 (ops 110-114)
I20260812 06:17:13.596553 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000024 (ops 115-119)
I20260812 06:17:13.596575 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000025 (ops 120-124)
I20260812 06:17:13.627523 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: LogGCOp(394effd027c045918b157614f0269922) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:13.628155 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:13.643620 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.015s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4583,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.644296 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:13.865590 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.221s	user 0.130s	sys 0.081s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":678,"lbm_read_time_us":13674,"lbm_reads_lt_1ms":665,"lbm_write_time_us":41923,"lbm_writes_lt_1ms":643,"mutex_wait_us":282,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:17:13.866361 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling UndoDeltaBlockGCOp(394effd027c045918b157614f0269922): 447 bytes on disk
I20260812 06:17:13.867053 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: UndoDeltaBlockGCOp(394effd027c045918b157614f0269922) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.868009 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=18.063937
I20260812 06:17:13.943735 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.076s	user 0.041s	sys 0.031s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":33034,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:13.944247 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:13.955642 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.956442 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:14.187999 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.231s	user 0.175s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":299,"lbm_read_time_us":15793,"lbm_reads_lt_1ms":672,"lbm_write_time_us":47288,"lbm_writes_lt_1ms":643,"mutex_wait_us":82,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":3000}
I20260812 06:17:14.188796 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:14.259495 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.070s	user 0.052s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29380,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.260037 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:14.273825 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.274365 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:14.468945 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.194s	user 0.129s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":844,"lbm_read_time_us":15698,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30542,"lbm_writes_lt_1ms":543,"mutex_wait_us":316,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:17:14.469660 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:14.535076 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.065s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21019,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.535912 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:14.554201 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.554872 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:14.754032 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.199s	user 0.126s	sys 0.059s 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":828,"lbm_read_time_us":13430,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33856,"lbm_writes_lt_1ms":543,"mutex_wait_us":96,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:14.754853 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:14.823346 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.068s	user 0.035s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24099,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.824084 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:14.836162 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.836704 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:15.039877 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.203s	user 0.130s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1034,"lbm_read_time_us":15381,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31521,"lbm_writes_lt_1ms":543,"mutex_wait_us":561,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:17:15.040910 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:15.096782 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.055s	user 0.039s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.097436 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:15.109454 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.110517 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:15.331792 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.221s	user 0.143s	sys 0.064s 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":1480,"lbm_read_time_us":13781,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33073,"lbm_writes_lt_1ms":543,"mutex_wait_us":554,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:17:15.332350 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:15.389739 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.057s	user 0.046s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25225,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":35072,"update_count":2000}
I20260812 06:17:15.390321 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:15.403738 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5056,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.404438 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushMRSOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:15.438704 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushMRSOp(394effd027c045918b157614f0269922) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":103,"dirs.run_cpu_time_us":338,"dirs.run_wall_time_us":1471,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1765,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:15.439464 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling LogGCOp(394effd027c045918b157614f0269922): free 136728441 bytes of WAL
I20260812 06:17:15.439716 25712 log_reader.cc:385] T 394effd027c045918b157614f0269922: removed 13 log segments from log reader
I20260812 06:17:15.439770 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000026 (ops 125-129)
I20260812 06:17:15.439826 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000027 (ops 130-134)
I20260812 06:17:15.439873 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000028 (ops 135-139)
I20260812 06:17:15.439904 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000029 (ops 140-144)
I20260812 06:17:15.439949 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000030 (ops 145-149)
I20260812 06:17:15.439989 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000031 (ops 150-154)
I20260812 06:17:15.440032 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000032 (ops 155-159)
I20260812 06:17:15.440068 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000033 (ops 160-164)
I20260812 06:17:15.440109 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000034 (ops 165-169)
I20260812 06:17:15.440150 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000035 (ops 170-174)
I20260812 06:17:15.440191 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000036 (ops 175-179)
I20260812 06:17:15.440230 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000037 (ops 180-184)
I20260812 06:17:15.440271 25712 log.cc:1079] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/394effd027c045918b157614f0269922/wal-000000038 (ops 185-189)
I20260812 06:17:15.472116 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: LogGCOp(394effd027c045918b157614f0269922) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:15.472575 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling UndoDeltaBlockGCOp(394effd027c045918b157614f0269922): 493 bytes on disk
I20260812 06:17:15.473223 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: UndoDeltaBlockGCOp(394effd027c045918b157614f0269922) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.473788 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=3.181125
I20260812 06:17:15.489483 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5107,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:15.489992 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=2.188937
I20260812 06:17:15.500139 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.500710 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:15.690526 25582 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.258s	user 1.912s	sys 0.157s
I20260812 06:17:15.735179 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.234s	user 0.158s	sys 0.074s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14951,"lbm_reads_lt_1ms":770,"lbm_write_time_us":40237,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:17:15.735769 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling FlushDeltaMemStoresOp(394effd027c045918b157614f0269922): perf score=14.095187
I20260812 06:17:15.770669 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: FlushDeltaMemStoresOp(394effd027c045918b157614f0269922) complete. Timing: real 0.035s	user 0.014s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17115,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.771181 25782 maintenance_manager.cc:419] P 92d04c1d7a044025bdc7ad968eb0c801: Scheduling MajorDeltaCompactionOp(394effd027c045918b157614f0269922): perf score=1.000000
I20260812 06:17:15.811074 25582 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.120s	user 0.004s	sys 0.000s
I20260812 06:17:15.811854 25582 tablet_server.cc:179] TabletServer@127.24.251.129:0 shutting down...
I20260812 06:17:15.895596 25712 maintenance_manager.cc:643] P 92d04c1d7a044025bdc7ad968eb0c801: MajorDeltaCompactionOp(394effd027c045918b157614f0269922) complete. Timing: real 0.124s	user 0.065s	sys 0.059s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1205,"lbm_read_time_us":9809,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25835,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:17:15.896425 25582 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:15.896880 25582 tablet_replica.cc:333] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801: stopping tablet replica
I20260812 06:17:15.897125 25582 raft_consensus.cc:2243] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.897420 25582 raft_consensus.cc:2272] T 394effd027c045918b157614f0269922 P 92d04c1d7a044025bdc7ad968eb0c801 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.903270 25582 tablet_server.cc:196] TabletServer@127.24.251.129:0 shutdown complete.
I20260812 06:17:15.937336 25582 master.cc:562] Master@127.24.251.190:35963 shutting down...
I20260812 06:17:15.941249 25582 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.941458 25582 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.941540 25582 tablet_replica.cc:333] T 00000000000000000000000000000000 P 79b888a7c6914d78934b113d85d97e4f: stopping tablet replica
I20260812 06:17:15.954257 25582 master.cc:584] Master@127.24.251.190:35963 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5908 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:16.044857 25582 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.251.190:33905
I20260812 06:17:16.045311 25582 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:16.047438 25820 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:16.047807 25821 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:16.047866 25824 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:16.047950 25582 server_base.cc:1061] running on GCE node
I20260812 06:17:16.048092 25582 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:16.048126 25582 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:16.048141 25582 hybrid_clock.cc:648] HybridClock initialized: now 1786515436048142 us; error 0 us; skew 500 ppm
I20260812 06:17:16.048969 25582 webserver.cc:533] Webserver started at http://127.24.251.190:46105/ using document root <none> and password file <none>
I20260812 06:17:16.049110 25582 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:16.049206 25582 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:16.049291 25582 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:16.049633 25582 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/master-0-root/instance:
uuid: "83ceca4c323047bcbb1b8967389b632f"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-9gcw"
I20260812 06:17:16.051101 25582 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:16.052011 25831 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:16.052261 25582 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:16.052356 25582 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/master-0-root
uuid: "83ceca4c323047bcbb1b8967389b632f"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-9gcw"
I20260812 06:17:16.052449 25582 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-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:16.062333 25582 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:16.062772 25582 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:16.067299 25582 rpc_server.cc:307] RPC server started. Bound to: 127.24.251.190:33905
I20260812 06:17:16.069852 25897 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.251.190:33905 every 8 connection(s)
I20260812 06:17:16.077250 25898 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:16.085741 25898 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f: Bootstrap starting.
I20260812 06:17:16.086576 25898 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:16.087661 25898 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f: No bootstrap required, opened a new log
I20260812 06:17:16.088052 25898 raft_consensus.cc:359] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "83ceca4c323047bcbb1b8967389b632f" member_type: VOTER }
I20260812 06:17:16.088143 25898 raft_consensus.cc:385] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:16.088166 25898 raft_consensus.cc:740] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 83ceca4c323047bcbb1b8967389b632f, State: Initialized, Role: FOLLOWER
I20260812 06:17:16.088272 25898 consensus_queue.cc:260] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [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: "83ceca4c323047bcbb1b8967389b632f" member_type: VOTER }
I20260812 06:17:16.088335 25898 raft_consensus.cc:399] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:16.088357 25898 raft_consensus.cc:493] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:16.088397 25898 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:16.089105 25898 raft_consensus.cc:515] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "83ceca4c323047bcbb1b8967389b632f" member_type: VOTER }
I20260812 06:17:16.089251 25898 leader_election.cc:304] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [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: 83ceca4c323047bcbb1b8967389b632f; no voters: 
I20260812 06:17:16.089428 25898 leader_election.cc:290] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:16.089610 25902 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:16.089885 25902 raft_consensus.cc:697] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 1 LEADER]: Becoming Leader. State: Replica: 83ceca4c323047bcbb1b8967389b632f, State: Running, Role: LEADER
I20260812 06:17:16.090015 25898 sys_catalog.cc:565] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:16.090025 25902 consensus_queue.cc:237] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [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: "83ceca4c323047bcbb1b8967389b632f" member_type: VOTER }
I20260812 06:17:16.090580 25903 sys_catalog.cc:455] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "83ceca4c323047bcbb1b8967389b632f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "83ceca4c323047bcbb1b8967389b632f" member_type: VOTER } }
I20260812 06:17:16.090627 25904 sys_catalog.cc:455] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 83ceca4c323047bcbb1b8967389b632f. Latest consensus state: current_term: 1 leader_uuid: "83ceca4c323047bcbb1b8967389b632f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "83ceca4c323047bcbb1b8967389b632f" member_type: VOTER } }
I20260812 06:17:16.090760 25904 sys_catalog.cc:458] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:16.091050 25903 sys_catalog.cc:458] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:16.091207 25909 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:16.092154 25909 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:16.092470 25582 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:16.094005 25909 catalog_manager.cc:1383] Generated new cluster ID: 5419acba2fb8498f86164a2594136a33
I20260812 06:17:16.094055 25909 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:16.102667 25909 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:16.103262 25909 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:16.114252 25909 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f: Generated new TSK 0
I20260812 06:17:16.114470 25909 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:16.125083 25582 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:16.127398 25928 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:16.127367 25924 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:16.127465 25925 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:16.127754 25582 server_base.cc:1061] running on GCE node
I20260812 06:17:16.127944 25582 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:16.127993 25582 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:16.128010 25582 hybrid_clock.cc:648] HybridClock initialized: now 1786515436128011 us; error 0 us; skew 500 ppm
I20260812 06:17:16.128954 25582 webserver.cc:533] Webserver started at http://127.24.251.129:44655/ using document root <none> and password file <none>
I20260812 06:17:16.129156 25582 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:16.129247 25582 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:16.129335 25582 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:16.129773 25582 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/instance:
uuid: "7aafaee2c3414d3aa479dbaf479e28ca"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-9gcw"
I20260812 06:17:16.131403 25582 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:16.132464 25933 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:16.132735 25582 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:16.132839 25582 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root
uuid: "7aafaee2c3414d3aa479dbaf479e28ca"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-9gcw"
I20260812 06:17:16.132932 25582 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-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:16.143765 25582 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:16.144136 25582 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:16.144419 25582 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:16.145290 25582 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:16.145363 25582 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:16.145453 25582 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:16.145494 25582 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:16.150514 25582 rpc_server.cc:307] RPC server started. Bound to: 127.24.251.129:35877
I20260812 06:17:16.150554 26007 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.251.129:35877 every 8 connection(s)
I20260812 06:17:16.160300 26008 heartbeater.cc:344] Connected to a master server at 127.24.251.190:33905
I20260812 06:17:16.160422 26008 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:16.160663 26008 heartbeater.cc:507] Master 127.24.251.190:33905 requested a full tablet report, sending...
I20260812 06:17:16.161396 25851 ts_manager.cc:194] Registered new tserver with Master: 7aafaee2c3414d3aa479dbaf479e28ca (127.24.251.129:35877)
I20260812 06:17:16.162004 25582 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011011843s
I20260812 06:17:16.162395 25851 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54684
I20260812 06:17:16.169495 25851 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54692:
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:16.178205 25968 tablet_service.cc:1511] Processing CreateTablet for tablet 478b1e08829549139e28b72353ff4382 (DEFAULT_TABLE table=heavy-update-compaction-test [id=76afcd7518fb4ac187f2ea164cefd5b9]), partition=
I20260812 06:17:16.178521 25968 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 478b1e08829549139e28b72353ff4382. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:16.180591 26024 tablet_bootstrap.cc:492] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Bootstrap starting.
I20260812 06:17:16.181528 26024 tablet_bootstrap.cc:654] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:16.182590 26024 tablet_bootstrap.cc:492] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: No bootstrap required, opened a new log
I20260812 06:17:16.182667 26024 ts_tablet_manager.cc:1403] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:16.183033 26024 raft_consensus.cc:359] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7aafaee2c3414d3aa479dbaf479e28ca" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 35877 } }
I20260812 06:17:16.183151 26024 raft_consensus.cc:385] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:16.183203 26024 raft_consensus.cc:740] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7aafaee2c3414d3aa479dbaf479e28ca, State: Initialized, Role: FOLLOWER
I20260812 06:17:16.183377 26024 consensus_queue.cc:260] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [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: "7aafaee2c3414d3aa479dbaf479e28ca" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 35877 } }
I20260812 06:17:16.183478 26024 raft_consensus.cc:399] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:16.183516 26024 raft_consensus.cc:493] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:16.183569 26024 raft_consensus.cc:3060] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:16.184358 26024 raft_consensus.cc:515] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7aafaee2c3414d3aa479dbaf479e28ca" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 35877 } }
I20260812 06:17:16.184499 26024 leader_election.cc:304] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [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: 7aafaee2c3414d3aa479dbaf479e28ca; no voters: 
I20260812 06:17:16.184664 26024 leader_election.cc:290] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:16.184803 26026 raft_consensus.cc:2804] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:16.185014 26024 ts_tablet_manager.cc:1434] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:16.185038 26008 heartbeater.cc:499] Master 127.24.251.190:33905 was elected leader, sending a full tablet report...
I20260812 06:17:16.185043 26026 raft_consensus.cc:697] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 1 LEADER]: Becoming Leader. State: Replica: 7aafaee2c3414d3aa479dbaf479e28ca, State: Running, Role: LEADER
I20260812 06:17:16.185292 26026 consensus_queue.cc:237] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [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: "7aafaee2c3414d3aa479dbaf479e28ca" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 35877 } }
I20260812 06:17:16.186663 25851 catalog_manager.cc:5719] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca reported cstate change: term changed from 0 to 1, leader changed from <none> to 7aafaee2c3414d3aa479dbaf479e28ca (127.24.251.129). New cstate: current_term: 1 leader_uuid: "7aafaee2c3414d3aa479dbaf479e28ca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7aafaee2c3414d3aa479dbaf479e28ca" member_type: VOTER last_known_addr { host: "127.24.251.129" port: 35877 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:16.247641 25582 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.023s	sys 0.000s
I20260812 06:17:16.401530 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushMRSOp(478b1e08829549139e28b72353ff4382): perf score=19.054940
I20260812 06:17:16.555377 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushMRSOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.153s	user 0.115s	sys 0.037s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":914,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41485,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:16.556048 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling LogGCOp(478b1e08829549139e28b72353ff4382): free 20290830 bytes of WAL
I20260812 06:17:16.556298 25938 log_reader.cc:385] T 478b1e08829549139e28b72353ff4382: removed 2 log segments from log reader
I20260812 06:17:16.556344 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000001 (ops 1-6)
I20260812 06:17:16.556377 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000002 (ops 7-10)
I20260812 06:17:16.561424 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: LogGCOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:16.562098 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling UndoDeltaBlockGCOp(478b1e08829549139e28b72353ff4382): 16411392 bytes on disk
I20260812 06:17:16.562711 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: UndoDeltaBlockGCOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.563284 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:16.577462 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.014s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.578056 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:16.748451 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.170s	user 0.110s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":662,"lbm_read_time_us":10677,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23898,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":349,"threads_started":5,"update_count":2000}
I20260812 06:17:16.749223 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:16.805402 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.056s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25468,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.805963 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:16.817739 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4499,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.818261 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:16.978333 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.160s	user 0.117s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":10674,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30334,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:17:16.979035 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:17.029276 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.050s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23102,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.029896 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:17.043399 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.043876 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:17.220973 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.177s	user 0.145s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":776,"lbm_read_time_us":10723,"lbm_reads_lt_1ms":564,"lbm_write_time_us":37561,"lbm_writes_lt_1ms":543,"mutex_wait_us":382,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:17:17.221593 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:17.272317 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.051s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20343,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.272915 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:17.285506 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.286341 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:17.446316 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.160s	user 0.115s	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":231,"lbm_read_time_us":11400,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28327,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21504,"update_count":2500}
I20260812 06:17:17.446905 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:17.504371 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.057s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23830,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.504849 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:17.516068 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.516885 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:17.711774 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.195s	user 0.111s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":273,"lbm_read_time_us":12071,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31408,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2500}
I20260812 06:17:17.712316 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:17.771611 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.059s	user 0.042s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23082,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.772183 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:17.783320 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.784240 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushMRSOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:17.815263 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushMRSOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1767,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:17.815884 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling LogGCOp(478b1e08829549139e28b72353ff4382): free 117302565 bytes of WAL
I20260812 06:17:17.816139 25938 log_reader.cc:385] T 478b1e08829549139e28b72353ff4382: removed 12 log segments from log reader
I20260812 06:17:17.816205 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000003 (ops 11-15)
I20260812 06:17:17.816257 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000004 (ops 16-20)
I20260812 06:17:17.816318 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000005 (ops 21-24)
I20260812 06:17:17.816360 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000006 (ops 25-29)
I20260812 06:17:17.816397 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000007 (ops 30-34)
I20260812 06:17:17.816437 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000008 (ops 35-38)
I20260812 06:17:17.816478 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000009 (ops 39-43)
I20260812 06:17:17.816517 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000010 (ops 44-48)
I20260812 06:17:17.816557 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000011 (ops 49-53)
I20260812 06:17:17.816597 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000012 (ops 54-58)
I20260812 06:17:17.816663 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000013 (ops 59-63)
I20260812 06:17:17.816704 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000014 (ops 64-68)
I20260812 06:17:17.843977 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: LogGCOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:17.844411 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=3.181125
I20260812 06:17:17.856475 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4693,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:17.856942 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:17.866797 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3813,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.867268 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:18.086300 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.219s	user 0.140s	sys 0.078s 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":280,"lbm_read_time_us":15458,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39634,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:17:18.087069 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=18.063937
I20260812 06:17:18.147614 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.060s	user 0.049s	sys 0.009s Metrics: {"bytes_written":20512322,"delete_count":0,"lbm_write_time_us":27292,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:18.148166 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:18.161062 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.161603 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:18.342936 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.181s	user 0.141s	sys 0.040s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877108,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":311,"lbm_read_time_us":14447,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36518,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":62080,"update_count":3000}
I20260812 06:17:18.343528 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:18.387944 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.044s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19451,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.388620 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:18.403693 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.404263 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:18.573132 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.169s	user 0.119s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1681,"lbm_read_time_us":10284,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30791,"lbm_writes_lt_1ms":543,"mutex_wait_us":337,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:17:18.573894 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling UndoDeltaBlockGCOp(478b1e08829549139e28b72353ff4382): 462 bytes on disk
I20260812 06:17:18.574481 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: UndoDeltaBlockGCOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":107,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.575290 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:18.630951 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.055s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23133,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.631575 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:18.784336 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.153s	user 0.109s	sys 0.036s 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":359,"lbm_read_time_us":10981,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23062,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2000}
I20260812 06:17:18.785084 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:18.839002 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.054s	user 0.028s	sys 0.013s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18922,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.839552 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:18.850612 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.852679 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:19.058238 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.205s	user 0.102s	sys 0.091s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":428,"lbm_read_time_us":12620,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31383,"lbm_writes_lt_1ms":543,"mutex_wait_us":93,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:17:19.058992 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:19.107414 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.048s	user 0.019s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20113,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.107967 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:19.121779 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.122573 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:19.286258 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.164s	user 0.118s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":10662,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30420,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:19.287061 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:19.342797 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.056s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24289,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.343289 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:19.354820 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.355362 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushMRSOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:19.391068 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushMRSOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.036s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":300,"dirs.run_wall_time_us":1627,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1790,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:19.391825 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling LogGCOp(478b1e08829549139e28b72353ff4382): free 132118263 bytes of WAL
I20260812 06:17:19.392122 25938 log_reader.cc:385] T 478b1e08829549139e28b72353ff4382: removed 13 log segments from log reader
I20260812 06:17:19.392180 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000015 (ops 69-72)
I20260812 06:17:19.392212 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000016 (ops 73-77)
I20260812 06:17:19.392272 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000017 (ops 78-82)
I20260812 06:17:19.392385 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000018 (ops 83-86)
I20260812 06:17:19.392432 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000019 (ops 87-91)
I20260812 06:17:19.392450 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000020 (ops 92-96)
I20260812 06:17:19.392488 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000021 (ops 97-101)
I20260812 06:17:19.392530 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000022 (ops 102-106)
I20260812 06:17:19.392575 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000023 (ops 107-111)
I20260812 06:17:19.392619 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000024 (ops 112-116)
I20260812 06:17:19.392661 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000025 (ops 117-121)
I20260812 06:17:19.392709 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000026 (ops 122-126)
I20260812 06:17:19.392753 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000027 (ops 127-130)
I20260812 06:17:19.420473 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: LogGCOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:19.420918 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling UndoDeltaBlockGCOp(478b1e08829549139e28b72353ff4382): 493 bytes on disk
I20260812 06:17:19.421535 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: UndoDeltaBlockGCOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.422428 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=6.157687
I20260812 06:17:19.457351 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.035s	user 0.016s	sys 0.018s Metrics: {"bytes_written":7425618,"delete_count":0,"lbm_write_time_us":10339,"lbm_writes_lt_1ms":184,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":905}
I20260812 06:17:19.457876 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:19.693252 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.235s	user 0.135s	sys 0.086s Metrics: {"cfile_cache_miss":714,"cfile_cache_miss_bytes":32200173,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":164,"lbm_read_time_us":15754,"lbm_reads_lt_1ms":750,"lbm_write_time_us":36086,"lbm_writes_lt_1ms":724,"mutex_wait_us":46,"peak_mem_usage":85108611,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":95,"threads_started":1,"update_count":3405}
I20260812 06:17:19.698426 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=19.056125
I20260812 06:17:19.767421 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.069s	user 0.032s	sys 0.034s Metrics: {"bytes_written":21291779,"delete_count":0,"lbm_write_time_us":31106,"lbm_writes_lt_1ms":522,"reinsert_count":0,"update_count":2595}
I20260812 06:17:19.768081 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:19.784564 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5900,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.785183 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:20.000869 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.215s	user 0.137s	sys 0.076s Metrics: {"cfile_cache_miss":651,"cfile_cache_miss_bytes":29656566,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1288,"lbm_read_time_us":16834,"lbm_reads_lt_1ms":691,"lbm_write_time_us":33638,"lbm_writes_lt_1ms":662,"mutex_wait_us":259,"peak_mem_usage":77362521,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3095}
I20260812 06:17:20.002528 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=16.079562
I20260812 06:17:20.068881 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.066s	user 0.034s	sys 0.011s Metrics: {"bytes_written":17763700,"delete_count":0,"lbm_write_time_us":21640,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2165}
I20260812 06:17:20.069527 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=5.165500
I20260812 06:17:20.095569 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.026s	user 0.016s	sys 0.004s Metrics: {"bytes_written":6851289,"delete_count":0,"lbm_write_time_us":9146,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:17:20.096098 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:20.315858 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.220s	user 0.131s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877111,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":13879,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35779,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:17:20.316511 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=18.063937
I20260812 06:17:20.388926 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.072s	user 0.035s	sys 0.019s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":26166,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:20.389423 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:20.400326 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.401235 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:20.617707 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.216s	user 0.147s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877108,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":15472,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37131,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":45312,"update_count":3000}
I20260812 06:17:20.618566 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:20.674005 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.055s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24641,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.674784 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:20.702453 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.027s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.702929 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:20.713516 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.010s	user 0.010s	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:20.714002 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:20.917757 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.204s	user 0.139s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1210,"lbm_read_time_us":14211,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32624,"lbm_writes_lt_1ms":643,"mutex_wait_us":413,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:20.918697 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=14.095187
I20260812 06:17:20.972823 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.054s	user 0.007s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22521,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.973493 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=3.181125
I20260812 06:17:20.992486 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.019s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5163,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:20.992998 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=2.188937
I20260812 06:17:21.002895 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3599,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:21.003463 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushMRSOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:21.037439 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushMRSOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.034s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1659,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2072,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:21.038304 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling LogGCOp(478b1e08829549139e28b72353ff4382): free 133024661 bytes of WAL
I20260812 06:17:21.038589 25938 log_reader.cc:385] T 478b1e08829549139e28b72353ff4382: removed 13 log segments from log reader
I20260812 06:17:21.038646 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000028 (ops 131-135)
I20260812 06:17:21.038708 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000029 (ops 136-140)
I20260812 06:17:21.038760 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000030 (ops 141-145)
I20260812 06:17:21.038830 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000031 (ops 146-150)
I20260812 06:17:21.038882 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000032 (ops 151-155)
I20260812 06:17:21.038954 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000033 (ops 156-160)
I20260812 06:17:21.038997 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000034 (ops 161-165)
I20260812 06:17:21.039065 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000035 (ops 166-170)
I20260812 06:17:21.039111 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000036 (ops 171-175)
I20260812 06:17:21.039160 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000037 (ops 176-180)
I20260812 06:17:21.039206 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000038 (ops 181-185)
I20260812 06:17:21.039252 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000039 (ops 186-190)
I20260812 06:17:21.039297 25938 log.cc:1079] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: Deleting log segment in path: /tmp/dist-test-tasko1L0yc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430125616-25582-0/minicluster-data/ts-0-root/wals/478b1e08829549139e28b72353ff4382/wal-000000040 (ops 191-194)
I20260812 06:17:21.071056 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: LogGCOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.033s	user 0.004s	sys 0.027s Metrics: {}
I20260812 06:17:21.071492 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=5.165500
I20260812 06:17:21.090922 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":6851278,"delete_count":0,"lbm_write_time_us":8233,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:17:21.091524 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:21.099941 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: FlushDeltaMemStoresOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.008s	user 0.006s	sys 0.000s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":2255,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:17:21.100533 26009 maintenance_manager.cc:419] P 7aafaee2c3414d3aa479dbaf479e28ca: Scheduling MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382): perf score=1.000000
I20260812 06:17:21.122987 25582 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.875s	user 1.817s	sys 0.147s
I20260812 06:17:21.225567 25582 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.102s	user 0.003s	sys 0.000s
I20260812 06:17:21.226104 25582 tablet_server.cc:179] TabletServer@127.24.251.129:0 shutting down...
I20260812 06:17:21.313557 25938 maintenance_manager.cc:643] P 7aafaee2c3414d3aa479dbaf479e28ca: MajorDeltaCompactionOp(478b1e08829549139e28b72353ff4382) complete. Timing: real 0.213s	user 0.153s	sys 0.060s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082203,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":758,"lbm_read_time_us":18124,"lbm_reads_lt_1ms":871,"lbm_write_time_us":37630,"lbm_writes_lt_1ms":843,"mutex_wait_us":21,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":164864,"thread_start_us":79,"threads_started":1,"update_count":4000}
I20260812 06:17:21.314293 25582 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:21.314780 25582 tablet_replica.cc:333] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca: stopping tablet replica
I20260812 06:17:21.314934 25582 raft_consensus.cc:2243] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:21.315137 25582 raft_consensus.cc:2272] T 478b1e08829549139e28b72353ff4382 P 7aafaee2c3414d3aa479dbaf479e28ca [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:21.321125 25582 tablet_server.cc:196] TabletServer@127.24.251.129:0 shutdown complete.
I20260812 06:17:21.387398 25582 master.cc:562] Master@127.24.251.190:33905 shutting down...
I20260812 06:17:21.390707 25582 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:21.390935 25582 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:21.391000 25582 tablet_replica.cc:333] T 00000000000000000000000000000000 P 83ceca4c323047bcbb1b8967389b632f: stopping tablet replica
I20260812 06:17:21.403299 25582 master.cc:584] Master@127.24.251.190:33905 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5442 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11351 ms total)

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