[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:44.001950 10495 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.63.254:44961
I20260812 06:16:44.002923 10495 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:44.003544 10495 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:44.009917 10506 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:16:44.009949 10509 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:16:44.010046 10495 server_base.cc:1061] running on GCE node
W20260812 06:16:44.010221 10503 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:44.010743 10495 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:44.010830 10495 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:44.010867 10495 hybrid_clock.cc:648] HybridClock initialized: now 1786515404010866 us; error 0 us; skew 500 ppm
I20260812 06:16:44.012521 10495 webserver.cc:533] Webserver started at http://127.10.63.254:40567/ using document root <none> and password file <none>
I20260812 06:16:44.012998 10495 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:44.013054 10495 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:44.013234 10495 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:44.014876 10495 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/master-0-root/instance:
uuid: "481a41e108274c9aaf938c4b8969ced0"
format_stamp: "Formatted at 2026-08-12 06:16:44 on dist-test-slave-x4qh"
I20260812 06:16:44.018093 10495 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:16:44.019992 10516 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:44.020895 10495 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:44.021014 10495 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/master-0-root
uuid: "481a41e108274c9aaf938c4b8969ced0"
format_stamp: "Formatted at 2026-08-12 06:16:44 on dist-test-slave-x4qh"
I20260812 06:16:44.021111 10495 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:44.043326 10495 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:44.044085 10495 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:44.044270 10495 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:44.052022 10594 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.63.254:44961 every 8 connection(s)
I20260812 06:16:44.052021 10495 rpc_server.cc:307] RPC server started. Bound to: 127.10.63.254:44961
I20260812 06:16:44.054255 10595 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:44.059686 10595 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0: Bootstrap starting.
I20260812 06:16:44.061995 10595 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:44.062866 10595 log.cc:826] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:44.064585 10595 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0: No bootstrap required, opened a new log
I20260812 06:16:44.067183 10595 raft_consensus.cc:359] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "481a41e108274c9aaf938c4b8969ced0" member_type: VOTER }
I20260812 06:16:44.067329 10595 raft_consensus.cc:385] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:44.067433 10595 raft_consensus.cc:740] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 481a41e108274c9aaf938c4b8969ced0, State: Initialized, Role: FOLLOWER
I20260812 06:16:44.068028 10595 consensus_queue.cc:260] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [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: "481a41e108274c9aaf938c4b8969ced0" member_type: VOTER }
I20260812 06:16:44.068189 10595 raft_consensus.cc:399] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:44.068257 10595 raft_consensus.cc:493] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:44.068406 10595 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:44.069170 10595 raft_consensus.cc:515] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "481a41e108274c9aaf938c4b8969ced0" member_type: VOTER }
I20260812 06:16:44.069586 10595 leader_election.cc:304] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [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: 481a41e108274c9aaf938c4b8969ced0; no voters: 
I20260812 06:16:44.069890 10595 leader_election.cc:290] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:44.070039 10601 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:44.070278 10601 raft_consensus.cc:697] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 1 LEADER]: Becoming Leader. State: Replica: 481a41e108274c9aaf938c4b8969ced0, State: Running, Role: LEADER
I20260812 06:16:44.070721 10601 consensus_queue.cc:237] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [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: "481a41e108274c9aaf938c4b8969ced0" member_type: VOTER }
I20260812 06:16:44.070814 10595 sys_catalog.cc:565] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:44.072649 10604 sys_catalog.cc:455] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 481a41e108274c9aaf938c4b8969ced0. Latest consensus state: current_term: 1 leader_uuid: "481a41e108274c9aaf938c4b8969ced0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "481a41e108274c9aaf938c4b8969ced0" member_type: VOTER } }
I20260812 06:16:44.072701 10603 sys_catalog.cc:455] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "481a41e108274c9aaf938c4b8969ced0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "481a41e108274c9aaf938c4b8969ced0" member_type: VOTER } }
I20260812 06:16:44.072793 10604 sys_catalog.cc:458] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:44.072793 10603 sys_catalog.cc:458] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:44.073149 10623 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:44.073288 10495 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:44.075295 10623 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:44.079850 10623 catalog_manager.cc:1383] Generated new cluster ID: 3c5f83677b2b4937b546b817da111b00
I20260812 06:16:44.079918 10623 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:44.101861 10623 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:44.102697 10623 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:44.107738 10623 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0: Generated new TSK 0
I20260812 06:16:44.108327 10623 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:44.138441 10495 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:44.141546 10638 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:44.141582 10643 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:16:44.141782 10495 server_base.cc:1061] running on GCE node
W20260812 06:16:44.141601 10640 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:44.142163 10495 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:44.142220 10495 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:44.142243 10495 hybrid_clock.cc:648] HybridClock initialized: now 1786515404142243 us; error 0 us; skew 500 ppm
I20260812 06:16:44.143208 10495 webserver.cc:533] Webserver started at http://127.10.63.193:44625/ using document root <none> and password file <none>
I20260812 06:16:44.143420 10495 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:44.143487 10495 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:44.143567 10495 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:44.144021 10495 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/instance:
uuid: "d89b9218c035402bb32fee9d6cf5dc8f"
format_stamp: "Formatted at 2026-08-12 06:16:44 on dist-test-slave-x4qh"
I20260812 06:16:44.145876 10495 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:44.146946 10651 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:44.147259 10495 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:44.147329 10495 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root
uuid: "d89b9218c035402bb32fee9d6cf5dc8f"
format_stamp: "Formatted at 2026-08-12 06:16:44 on dist-test-slave-x4qh"
I20260812 06:16:44.147439 10495 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:44.163153 10495 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:44.163884 10495 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:44.164427 10495 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:44.165288 10495 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:44.165341 10495 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:44.165406 10495 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:44.165446 10495 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:44.172355 10495 rpc_server.cc:307] RPC server started. Bound to: 127.10.63.193:35057
I20260812 06:16:44.172549 10758 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.63.193:35057 every 8 connection(s)
I20260812 06:16:44.182037 10760 heartbeater.cc:344] Connected to a master server at 127.10.63.254:44961
I20260812 06:16:44.182291 10760 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:44.182744 10760 heartbeater.cc:507] Master 127.10.63.254:44961 requested a full tablet report, sending...
I20260812 06:16:44.184300 10539 ts_manager.cc:194] Registered new tserver with Master: d89b9218c035402bb32fee9d6cf5dc8f (127.10.63.193:35057)
I20260812 06:16:44.184437 10495 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011266688s
I20260812 06:16:44.185781 10539 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42278
I20260812 06:16:44.193711 10539 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42280:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:44.207989 10704 tablet_service.cc:1511] Processing CreateTablet for tablet f2e70262f06b4f1995bc063075dc72e2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d090df906bc64100acac93f754ada319]), partition=
I20260812 06:16:44.208477 10704 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f2e70262f06b4f1995bc063075dc72e2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:44.210600 10783 tablet_bootstrap.cc:492] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Bootstrap starting.
I20260812 06:16:44.211731 10783 tablet_bootstrap.cc:654] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:44.213181 10783 tablet_bootstrap.cc:492] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: No bootstrap required, opened a new log
I20260812 06:16:44.213299 10783 ts_tablet_manager.cc:1403] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:44.213765 10783 raft_consensus.cc:359] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d89b9218c035402bb32fee9d6cf5dc8f" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 35057 } }
I20260812 06:16:44.213892 10783 raft_consensus.cc:385] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:44.213941 10783 raft_consensus.cc:740] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d89b9218c035402bb32fee9d6cf5dc8f, State: Initialized, Role: FOLLOWER
I20260812 06:16:44.214078 10783 consensus_queue.cc:260] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [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: "d89b9218c035402bb32fee9d6cf5dc8f" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 35057 } }
I20260812 06:16:44.214169 10783 raft_consensus.cc:399] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:44.214217 10783 raft_consensus.cc:493] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:44.214270 10783 raft_consensus.cc:3060] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:44.215060 10783 raft_consensus.cc:515] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d89b9218c035402bb32fee9d6cf5dc8f" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 35057 } }
I20260812 06:16:44.215217 10783 leader_election.cc:304] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [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: d89b9218c035402bb32fee9d6cf5dc8f; no voters: 
I20260812 06:16:44.215451 10783 leader_election.cc:290] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:44.215553 10789 raft_consensus.cc:2804] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:44.215764 10789 raft_consensus.cc:697] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 1 LEADER]: Becoming Leader. State: Replica: d89b9218c035402bb32fee9d6cf5dc8f, State: Running, Role: LEADER
I20260812 06:16:44.215907 10783 ts_tablet_manager.cc:1434] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:44.215965 10789 consensus_queue.cc:237] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [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: "d89b9218c035402bb32fee9d6cf5dc8f" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 35057 } }
I20260812 06:16:44.216326 10760 heartbeater.cc:499] Master 127.10.63.254:44961 was elected leader, sending a full tablet report...
I20260812 06:16:44.219019 10539 catalog_manager.cc:5719] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f reported cstate change: term changed from 0 to 1, leader changed from <none> to d89b9218c035402bb32fee9d6cf5dc8f (127.10.63.193). New cstate: current_term: 1 leader_uuid: "d89b9218c035402bb32fee9d6cf5dc8f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d89b9218c035402bb32fee9d6cf5dc8f" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 35057 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:44.281495 10495 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.020s	sys 0.004s
I20260812 06:16:44.423677 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushMRSOp(f2e70262f06b4f1995bc063075dc72e2): perf score=19.054940
I20260812 06:16:44.617601 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushMRSOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.194s	user 0.165s	sys 0.024s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":320,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":927,"drs_written":1,"lbm_read_time_us":117,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46416,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":182,"threads_started":1,"update_count":1500}
I20260812 06:16:44.618960 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling LogGCOp(f2e70262f06b4f1995bc063075dc72e2): free 20743880 bytes of WAL
I20260812 06:16:44.619412 10663 log_reader.cc:385] T f2e70262f06b4f1995bc063075dc72e2: removed 2 log segments from log reader
I20260812 06:16:44.619499 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000001 (ops 1-6)
I20260812 06:16:44.619575 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000002 (ops 7-11)
I20260812 06:16:44.625581 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: LogGCOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {}
I20260812 06:16:44.626093 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:44.659765 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.033s	user 0.009s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5508,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.660233 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling UndoDeltaBlockGCOp(f2e70262f06b4f1995bc063075dc72e2): 16411394 bytes on disk
I20260812 06:16:44.660792 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: UndoDeltaBlockGCOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.661194 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:44.671860 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4287,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.672292 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:44.844617 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.172s	user 0.118s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":467,"lbm_read_time_us":12082,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28143,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":253,"threads_started":5,"update_count":2500}
I20260812 06:16:44.845129 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=10.126437
I20260812 06:16:44.889780 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.044s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18012,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:44.890308 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:44.900889 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4254,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.901324 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:45.031203 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.130s	user 0.105s	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":1211,"lbm_read_time_us":9449,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25303,"lbm_writes_lt_1ms":443,"mutex_wait_us":290,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.031750 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=10.126437
I20260812 06:16:45.072942 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.041s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13729,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.073432 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:45.084463 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.085156 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:45.204402 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.119s	user 0.091s	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":1446,"lbm_read_time_us":9210,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22683,"lbm_writes_lt_1ms":443,"mutex_wait_us":313,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:16:45.206758 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=10.126437
I20260812 06:16:45.245177 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.037s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16181,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.245700 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:45.263345 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.017s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.263952 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:45.407605 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.140s	user 0.117s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":244,"lbm_read_time_us":7656,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29221,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:45.408108 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=10.126437
I20260812 06:16:45.460062 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.052s	user 0.028s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20676,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.460621 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:45.471101 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4196,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.471577 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:45.622900 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.151s	user 0.106s	sys 0.045s 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":548,"lbm_read_time_us":11394,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23611,"lbm_writes_lt_1ms":443,"mutex_wait_us":120,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:16:45.626689 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=10.126437
I20260812 06:16:45.664498 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.037s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15967,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.664949 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:45.676798 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4354,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.677321 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:45.805627 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.128s	user 0.103s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":9917,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24864,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23296,"update_count":2000}
I20260812 06:16:45.806349 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=10.126437
I20260812 06:16:45.844805 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.038s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15789,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.845387 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:45.858234 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.858731 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushMRSOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:45.890208 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushMRSOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1274,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1678,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:45.890995 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling LogGCOp(f2e70262f06b4f1995bc063075dc72e2): free 115943174 bytes of WAL
I20260812 06:16:45.891208 10663 log_reader.cc:385] T f2e70262f06b4f1995bc063075dc72e2: removed 11 log segments from log reader
I20260812 06:16:45.891254 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000003 (ops 12-17)
I20260812 06:16:45.891283 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000004 (ops 18-22)
I20260812 06:16:45.891348 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000005 (ops 23-27)
I20260812 06:16:45.891431 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000006 (ops 28-32)
I20260812 06:16:45.891470 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000007 (ops 33-36)
I20260812 06:16:45.891511 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000008 (ops 37-41)
I20260812 06:16:45.891547 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000009 (ops 42-46)
I20260812 06:16:45.891584 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000010 (ops 47-51)
I20260812 06:16:45.891623 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000011 (ops 52-56)
I20260812 06:16:45.891660 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000012 (ops 57-61)
I20260812 06:16:45.891697 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000013 (ops 62-66)
I20260812 06:16:45.919962 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: LogGCOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.029s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:16:45.920324 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=4.173312
I20260812 06:16:45.937175 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":5702609,"delete_count":0,"lbm_write_time_us":6749,"lbm_writes_lt_1ms":142,"reinsert_count":0,"update_count":695}
I20260812 06:16:45.937664 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.196750
I20260812 06:16:45.949832 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2502679,"delete_count":0,"lbm_write_time_us":3917,"lbm_writes_lt_1ms":64,"reinsert_count":0,"update_count":305}
I20260812 06:16:45.950445 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling UndoDeltaBlockGCOp(f2e70262f06b4f1995bc063075dc72e2): 462 bytes on disk
I20260812 06:16:45.950938 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: UndoDeltaBlockGCOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.951546 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:46.127790 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.176s	user 0.116s	sys 0.054s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877302,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":751,"lbm_read_time_us":10716,"lbm_reads_lt_1ms":666,"lbm_write_time_us":36398,"lbm_writes_lt_1ms":643,"mutex_wait_us":219,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:16:46.128474 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=14.095187
I20260812 06:16:46.183079 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.054s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23323,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.183672 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:46.201108 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.201584 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:46.353106 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.151s	user 0.116s	sys 0.035s 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":1127,"lbm_read_time_us":9509,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27778,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:46.353567 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=14.095187
I20260812 06:16:46.422732 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.069s	user 0.045s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24665,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.423163 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:46.433408 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3972,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.433869 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:46.615749 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.181s	user 0.126s	sys 0.047s 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":132,"lbm_read_time_us":11768,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31062,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:16:46.616526 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=14.095187
I20260812 06:16:46.678532 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.062s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22092,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.679036 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:46.689679 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.690114 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:46.857991 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.168s	user 0.129s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":397,"lbm_read_time_us":12418,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29814,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:16:46.858750 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=11.118625
I20260812 06:16:46.893591 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.035s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14713,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:46.894287 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:46.908418 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5456,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.908991 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:47.070225 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.161s	user 0.073s	sys 0.076s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1091,"lbm_read_time_us":9977,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24717,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:16:47.070843 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=14.095187
I20260812 06:16:47.119170 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.048s	user 0.034s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.119738 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:47.130829 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.131441 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:47.280647 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.149s	user 0.107s	sys 0.040s 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":613,"lbm_read_time_us":12339,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29850,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:16:47.281311 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=11.118625
I20260812 06:16:47.317960 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.036s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15455,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:47.318470 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:47.334525 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.016s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4594,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.336886 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushMRSOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:47.375078 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushMRSOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.038s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1463,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1531,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:47.376039 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling UndoDeltaBlockGCOp(f2e70262f06b4f1995bc063075dc72e2): 482 bytes on disk
I20260812 06:16:47.376492 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: UndoDeltaBlockGCOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.377051 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=3.181125
I20260812 06:16:47.394740 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6975,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:47.395181 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling LogGCOp(f2e70262f06b4f1995bc063075dc72e2): free 133024379 bytes of WAL
I20260812 06:16:47.395437 10663 log_reader.cc:385] T f2e70262f06b4f1995bc063075dc72e2: removed 13 log segments from log reader
I20260812 06:16:47.395483 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000014 (ops 67-71)
I20260812 06:16:47.395511 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000015 (ops 72-76)
I20260812 06:16:47.395581 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000016 (ops 77-81)
I20260812 06:16:47.395623 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000017 (ops 82-86)
I20260812 06:16:47.395664 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000018 (ops 87-91)
I20260812 06:16:47.395723 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000019 (ops 92-96)
I20260812 06:16:47.395763 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000020 (ops 97-101)
I20260812 06:16:47.395812 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000021 (ops 102-106)
I20260812 06:16:47.395851 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000022 (ops 107-111)
I20260812 06:16:47.395891 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000023 (ops 112-116)
I20260812 06:16:47.395931 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000024 (ops 117-121)
I20260812 06:16:47.395972 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000025 (ops 122-126)
I20260812 06:16:47.396010 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000026 (ops 127-130)
I20260812 06:16:47.423540 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: LogGCOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.028s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:16:47.423967 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:47.434897 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.435298 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:47.455745 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.020s	user 0.012s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3560,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.456310 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:47.692935 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.236s	user 0.144s	sys 0.091s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":319,"lbm_read_time_us":17709,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41723,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:16:47.693467 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=15.087375
I20260812 06:16:47.756239 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.063s	user 0.029s	sys 0.032s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":22487,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:47.756803 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=3.181125
I20260812 06:16:47.774608 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":5251341,"delete_count":0,"lbm_write_time_us":7438,"lbm_writes_lt_1ms":131,"mutex_wait_us":94,"reinsert_count":0,"update_count":640}
I20260812 06:16:47.775094 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.196750
I20260812 06:16:47.782545 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.007s	user 0.002s	sys 0.003s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":2611,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:16:47.783088 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:47.993924 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.211s	user 0.127s	sys 0.083s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877184,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":732,"lbm_read_time_us":15600,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35792,"lbm_writes_lt_1ms":643,"mutex_wait_us":327,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":3000}
I20260812 06:16:47.994509 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=14.095187
I20260812 06:16:48.060277 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.065s	user 0.040s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29852,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.060817 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:48.081357 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.020s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6463,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.081852 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:48.247071 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.165s	user 0.103s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":355,"lbm_read_time_us":12349,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29418,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:16:48.247794 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=14.095187
I20260812 06:16:48.296325 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.048s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22623,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:16:48.296913 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:48.312764 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.313337 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:48.478641 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.165s	user 0.113s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":525,"lbm_read_time_us":11237,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29350,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:16:48.479166 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=14.095187
I20260812 06:16:48.541899 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.062s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25000,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:16:48.542477 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:48.553412 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4325,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.553885 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:48.732899 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.179s	user 0.098s	sys 0.075s 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":710,"lbm_read_time_us":13002,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30086,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:16:48.733520 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=11.118625
I20260812 06:16:48.783128 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.049s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20214,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:48.783792 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:48.805382 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.021s	user 0.001s	sys 0.018s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.805883 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=2.188937
I20260812 06:16:48.820209 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5213,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.820832 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushMRSOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:48.851728 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushMRSOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1275,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1624,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:48.852461 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:49.039486 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.187s	user 0.105s	sys 0.081s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":361,"lbm_read_time_us":12030,"lbm_reads_lt_1ms":565,"lbm_write_time_us":52393,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:16:49.040238 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling LogGCOp(f2e70262f06b4f1995bc063075dc72e2): free 112239561 bytes of WAL
I20260812 06:16:49.040491 10663 log_reader.cc:385] T f2e70262f06b4f1995bc063075dc72e2: removed 11 log segments from log reader
I20260812 06:16:49.040551 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000027 (ops 131-135)
I20260812 06:16:49.040588 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000028 (ops 136-140)
I20260812 06:16:49.040619 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000029 (ops 141-144)
I20260812 06:16:49.040702 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000030 (ops 145-149)
I20260812 06:16:49.040757 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000031 (ops 150-154)
I20260812 06:16:49.040781 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000032 (ops 155-159)
I20260812 06:16:49.040843 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000033 (ops 160-164)
I20260812 06:16:49.040881 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000034 (ops 165-169)
I20260812 06:16:49.040938 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000035 (ops 170-174)
I20260812 06:16:49.040972 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000036 (ops 175-179)
I20260812 06:16:49.040998 10663 log.cc:1079] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/f2e70262f06b4f1995bc063075dc72e2/wal-000000037 (ops 180-184)
I20260812 06:16:49.077220 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: LogGCOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.037s	user 0.000s	sys 0.035s Metrics: {}
I20260812 06:16:49.077914 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling UndoDeltaBlockGCOp(f2e70262f06b4f1995bc063075dc72e2): 448 bytes on disk
I20260812 06:16:49.078490 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: UndoDeltaBlockGCOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4}
I20260812 06:16:49.079061 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=16.079562
I20260812 06:16:49.142830 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.064s	user 0.028s	sys 0.028s Metrics: {"bytes_written":18584180,"delete_count":0,"lbm_write_time_us":22385,"lbm_writes_lt_1ms":456,"mutex_wait_us":184,"reinsert_count":0,"update_count":2265}
I20260812 06:16:49.143488 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2): perf score=4.173312
I20260812 06:16:49.158463 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: FlushDeltaMemStoresOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":6030807,"delete_count":0,"lbm_write_time_us":6284,"lbm_writes_lt_1ms":150,"reinsert_count":0,"update_count":735}
I20260812 06:16:49.159003 10762 maintenance_manager.cc:419] P d89b9218c035402bb32fee9d6cf5dc8f: Scheduling MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2): perf score=1.000000
I20260812 06:16:49.249679 10495 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.968s	user 1.794s	sys 0.153s
I20260812 06:16:49.338681 10495 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.088s	user 0.003s	sys 0.000s
I20260812 06:16:49.339560 10495 tablet_server.cc:179] TabletServer@127.10.63.193:0 shutting down...
I20260812 06:16:49.357630 10663 maintenance_manager.cc:643] P d89b9218c035402bb32fee9d6cf5dc8f: MajorDeltaCompactionOp(f2e70262f06b4f1995bc063075dc72e2) complete. Timing: real 0.198s	user 0.154s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":811,"lbm_read_time_us":14819,"lbm_reads_lt_1ms":668,"lbm_write_time_us":33942,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":3000}
I20260812 06:16:49.358270 10495 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:49.358790 10495 tablet_replica.cc:333] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f: stopping tablet replica
I20260812 06:16:49.359005 10495 raft_consensus.cc:2243] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:49.359243 10495 raft_consensus.cc:2272] T f2e70262f06b4f1995bc063075dc72e2 P d89b9218c035402bb32fee9d6cf5dc8f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:49.376564 10495 tablet_server.cc:196] TabletServer@127.10.63.193:0 shutdown complete.
I20260812 06:16:49.413784 10495 master.cc:562] Master@127.10.63.254:44961 shutting down...
I20260812 06:16:49.417826 10495 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:49.418001 10495 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:49.418057 10495 tablet_replica.cc:333] T 00000000000000000000000000000000 P 481a41e108274c9aaf938c4b8969ced0: stopping tablet replica
I20260812 06:16:49.430440 10495 master.cc:584] Master@127.10.63.254:44961 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5523 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:49.537714 10495 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.63.254:33389
I20260812 06:16:49.538074 10495 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:49.540359 10495 server_base.cc:1061] running on GCE node
W20260812 06:16:49.540336 10814 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:16:49.540463 10811 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:49.540542 10818 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:16:49.540746 10495 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:49.540793 10495 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:49.540809 10495 hybrid_clock.cc:648] HybridClock initialized: now 1786515409540809 us; error 0 us; skew 500 ppm
I20260812 06:16:49.541687 10495 webserver.cc:533] Webserver started at http://127.10.63.254:46757/ using document root <none> and password file <none>
I20260812 06:16:49.541880 10495 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:49.541929 10495 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:49.542032 10495 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:49.542412 10495 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/master-0-root/instance:
uuid: "20cd321cbfb64dc09192abf63c3630dd"
format_stamp: "Formatted at 2026-08-12 06:16:49 on dist-test-slave-x4qh"
I20260812 06:16:49.544154 10495 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:49.545121 10828 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:49.545359 10495 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:49.545451 10495 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/master-0-root
uuid: "20cd321cbfb64dc09192abf63c3630dd"
format_stamp: "Formatted at 2026-08-12 06:16:49 on dist-test-slave-x4qh"
I20260812 06:16:49.545537 10495 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:49.553712 10495 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:49.554064 10495 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:49.558398 10495 rpc_server.cc:307] RPC server started. Bound to: 127.10.63.254:33389
I20260812 06:16:49.564093 10919 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.63.254:33389 every 8 connection(s)
I20260812 06:16:49.564575 10921 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:49.566329 10921 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd: Bootstrap starting.
I20260812 06:16:49.567085 10921 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:49.568176 10921 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd: No bootstrap required, opened a new log
I20260812 06:16:49.568573 10921 raft_consensus.cc:359] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20cd321cbfb64dc09192abf63c3630dd" member_type: VOTER }
I20260812 06:16:49.568681 10921 raft_consensus.cc:385] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:49.568739 10921 raft_consensus.cc:740] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 20cd321cbfb64dc09192abf63c3630dd, State: Initialized, Role: FOLLOWER
I20260812 06:16:49.568928 10921 consensus_queue.cc:260] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [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: "20cd321cbfb64dc09192abf63c3630dd" member_type: VOTER }
I20260812 06:16:49.569024 10921 raft_consensus.cc:399] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:49.569074 10921 raft_consensus.cc:493] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:49.569129 10921 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:49.569921 10921 raft_consensus.cc:515] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20cd321cbfb64dc09192abf63c3630dd" member_type: VOTER }
I20260812 06:16:49.570070 10921 leader_election.cc:304] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [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: 20cd321cbfb64dc09192abf63c3630dd; no voters: 
I20260812 06:16:49.570286 10921 leader_election.cc:290] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:49.570433 10928 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:49.570714 10928 raft_consensus.cc:697] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 1 LEADER]: Becoming Leader. State: Replica: 20cd321cbfb64dc09192abf63c3630dd, State: Running, Role: LEADER
I20260812 06:16:49.570740 10921 sys_catalog.cc:565] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:49.570873 10928 consensus_queue.cc:237] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [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: "20cd321cbfb64dc09192abf63c3630dd" member_type: VOTER }
I20260812 06:16:49.571336 10929 sys_catalog.cc:455] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "20cd321cbfb64dc09192abf63c3630dd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20cd321cbfb64dc09192abf63c3630dd" member_type: VOTER } }
I20260812 06:16:49.571475 10929 sys_catalog.cc:458] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:49.571353 10930 sys_catalog.cc:455] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [sys.catalog]: SysCatalogTable state changed. Reason: New leader 20cd321cbfb64dc09192abf63c3630dd. Latest consensus state: current_term: 1 leader_uuid: "20cd321cbfb64dc09192abf63c3630dd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20cd321cbfb64dc09192abf63c3630dd" member_type: VOTER } }
I20260812 06:16:49.571768 10930 sys_catalog.cc:458] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:49.571810 10945 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:49.572777 10945 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:49.572988 10495 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:49.574638 10945 catalog_manager.cc:1383] Generated new cluster ID: c78c08213114403a82213b9fc35a852e
I20260812 06:16:49.574707 10945 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:49.606307 10945 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:49.606885 10945 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:49.613225 10945 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd: Generated new TSK 0
I20260812 06:16:49.613415 10945 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:49.637670 10495 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:49.639655 10963 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:16:49.639721 10962 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:49.639798 10965 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:16:49.640138 10495 server_base.cc:1061] running on GCE node
I20260812 06:16:49.640327 10495 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:49.640368 10495 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:49.640385 10495 hybrid_clock.cc:648] HybridClock initialized: now 1786515409640385 us; error 0 us; skew 500 ppm
I20260812 06:16:49.641310 10495 webserver.cc:533] Webserver started at http://127.10.63.193:45769/ using document root <none> and password file <none>
I20260812 06:16:49.641510 10495 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:49.641582 10495 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:49.641672 10495 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:49.642151 10495 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/instance:
uuid: "8ed12603a4b846cda81861fb4cd65de6"
format_stamp: "Formatted at 2026-08-12 06:16:49 on dist-test-slave-x4qh"
I20260812 06:16:49.643682 10495 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:49.644614 10977 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:49.644989 10495 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:49.645054 10495 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root
uuid: "8ed12603a4b846cda81861fb4cd65de6"
format_stamp: "Formatted at 2026-08-12 06:16:49 on dist-test-slave-x4qh"
I20260812 06:16:49.645151 10495 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:49.655112 10495 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:49.655588 10495 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:49.655911 10495 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:49.656388 10495 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:49.656426 10495 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:49.656486 10495 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:49.656529 10495 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:49.660964 10495 rpc_server.cc:307] RPC server started. Bound to: 127.10.63.193:46355
I20260812 06:16:49.661967 11080 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.63.193:46355 every 8 connection(s)
I20260812 06:16:49.675236 11081 heartbeater.cc:344] Connected to a master server at 127.10.63.254:33389
I20260812 06:16:49.675423 11081 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:49.675709 11081 heartbeater.cc:507] Master 127.10.63.254:33389 requested a full tablet report, sending...
I20260812 06:16:49.676411 10857 ts_manager.cc:194] Registered new tserver with Master: 8ed12603a4b846cda81861fb4cd65de6 (127.10.63.193:46355)
I20260812 06:16:49.677147 10857 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52018
I20260812 06:16:49.677326 10495 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015458569s
I20260812 06:16:49.684664 10857 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52020:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:49.693249 11030 tablet_service.cc:1511] Processing CreateTablet for tablet 5561da7ca4624576a5459f470a9f1f91 (DEFAULT_TABLE table=heavy-update-compaction-test [id=206bc2abe38147279a8087909c1167af]), partition=
I20260812 06:16:49.693557 11030 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5561da7ca4624576a5459f470a9f1f91. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:49.695842 11107 tablet_bootstrap.cc:492] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Bootstrap starting.
I20260812 06:16:49.696688 11107 tablet_bootstrap.cc:654] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:49.697732 11107 tablet_bootstrap.cc:492] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: No bootstrap required, opened a new log
I20260812 06:16:49.697846 11107 ts_tablet_manager.cc:1403] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:49.698342 11107 raft_consensus.cc:359] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8ed12603a4b846cda81861fb4cd65de6" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 46355 } }
I20260812 06:16:49.698428 11107 raft_consensus.cc:385] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:49.698449 11107 raft_consensus.cc:740] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8ed12603a4b846cda81861fb4cd65de6, State: Initialized, Role: FOLLOWER
I20260812 06:16:49.698609 11107 consensus_queue.cc:260] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [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: "8ed12603a4b846cda81861fb4cd65de6" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 46355 } }
I20260812 06:16:49.698704 11107 raft_consensus.cc:399] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:49.698750 11107 raft_consensus.cc:493] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:49.698848 11107 raft_consensus.cc:3060] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:49.699645 11107 raft_consensus.cc:515] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8ed12603a4b846cda81861fb4cd65de6" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 46355 } }
I20260812 06:16:49.699793 11107 leader_election.cc:304] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [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: 8ed12603a4b846cda81861fb4cd65de6; no voters: 
I20260812 06:16:49.700013 11107 leader_election.cc:290] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:49.700150 11111 raft_consensus.cc:2804] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:49.700398 11107 ts_tablet_manager.cc:1434] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:49.700445 11081 heartbeater.cc:499] Master 127.10.63.254:33389 was elected leader, sending a full tablet report...
I20260812 06:16:49.700409 11111 raft_consensus.cc:697] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 1 LEADER]: Becoming Leader. State: Replica: 8ed12603a4b846cda81861fb4cd65de6, State: Running, Role: LEADER
I20260812 06:16:49.700652 11111 consensus_queue.cc:237] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [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: "8ed12603a4b846cda81861fb4cd65de6" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 46355 } }
I20260812 06:16:49.701849 10857 catalog_manager.cc:5719] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8ed12603a4b846cda81861fb4cd65de6 (127.10.63.193). New cstate: current_term: 1 leader_uuid: "8ed12603a4b846cda81861fb4cd65de6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8ed12603a4b846cda81861fb4cd65de6" member_type: VOTER last_known_addr { host: "127.10.63.193" port: 46355 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:49.761278 10495 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.013s	sys 0.009s
I20260812 06:16:49.912531 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushMRSOp(5561da7ca4624576a5459f470a9f1f91): perf score=19.054940
I20260812 06:16:50.058228 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushMRSOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.145s	user 0.091s	sys 0.051s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":849,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36203,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:50.058944 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling LogGCOp(5561da7ca4624576a5459f470a9f1f91): free 20743880 bytes of WAL
I20260812 06:16:50.059242 10985 log_reader.cc:385] T 5561da7ca4624576a5459f470a9f1f91: removed 2 log segments from log reader
I20260812 06:16:50.059310 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000001 (ops 1-6)
I20260812 06:16:50.059396 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000002 (ops 7-11)
I20260812 06:16:50.065280 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: LogGCOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.006s	user 0.002s	sys 0.003s Metrics: {}
I20260812 06:16:50.065724 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling UndoDeltaBlockGCOp(5561da7ca4624576a5459f470a9f1f91): 16411395 bytes on disk
I20260812 06:16:50.066180 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: UndoDeltaBlockGCOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:16:50.066592 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:50.078732 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.079414 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.000000
I20260812 06:16:50.228603 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.149s	user 0.100s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":589,"lbm_read_time_us":11524,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25235,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"thread_start_us":329,"threads_started":5,"update_count":2000}
I20260812 06:16:50.229305 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=10.126437
I20260812 06:16:50.273603 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19573,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.274107 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:50.291590 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.017s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6648,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.292093 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.000000
I20260812 06:16:50.447299 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.155s	user 0.111s	sys 0.041s 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":168,"lbm_read_time_us":10753,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25475,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2000}
I20260812 06:16:50.448074 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=10.126437
I20260812 06:16:50.489068 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.041s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18356,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.489490 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:50.500128 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.500880 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.000000
I20260812 06:16:50.642753 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.142s	user 0.104s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":9457,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27282,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:16:50.643486 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=10.126437
I20260812 06:16:50.683830 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.040s	user 0.029s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16898,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.684376 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:50.699456 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.700011 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.000000
I20260812 06:16:50.823712 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.123s	user 0.088s	sys 0.034s 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":324,"lbm_read_time_us":9378,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24791,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:16:50.824642 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=10.126437
I20260812 06:16:50.868136 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.043s	user 0.012s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13277,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.868716 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.000000
I20260812 06:16:50.879456 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.011s	user 0.003s	sys 0.004s Metrics: {"bytes_written":1271930,"delete_count":0,"lbm_write_time_us":2183,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:16:50.879896 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.196750
I20260812 06:16:50.887691 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":2963,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:16:50.888084 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.000000
I20260812 06:16:51.034206 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.146s	user 0.106s	sys 0.040s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672301,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":158,"lbm_read_time_us":11610,"lbm_reads_lt_1ms":473,"lbm_write_time_us":23525,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:16:51.034888 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=10.126437
I20260812 06:16:51.071497 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.036s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15573,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:51.072099 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:51.092633 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.020s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5747,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.093217 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.000000
I20260812 06:16:51.231691 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.138s	user 0.110s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":760,"lbm_read_time_us":10099,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26678,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:16:51.232321 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=11.118625
I20260812 06:16:51.271842 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.039s	user 0.039s	sys 0.000s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17279,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:51.272352 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:51.290127 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6415,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.290705 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushMRSOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.000000
I20260812 06:16:51.337411 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushMRSOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.046s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1276,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1874,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:51.338220 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=3.181125
I20260812 06:16:51.352137 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5058,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:51.352686 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling LogGCOp(5561da7ca4624576a5459f470a9f1f91): free 112239318 bytes of WAL
I20260812 06:16:51.352986 10985 log_reader.cc:385] T 5561da7ca4624576a5459f470a9f1f91: removed 11 log segments from log reader
I20260812 06:16:51.353047 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000003 (ops 12-16)
I20260812 06:16:51.353085 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000004 (ops 17-21)
I20260812 06:16:51.353111 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000005 (ops 22-26)
I20260812 06:16:51.353138 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000006 (ops 27-31)
I20260812 06:16:51.353174 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000007 (ops 32-36)
I20260812 06:16:51.353196 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000008 (ops 37-41)
I20260812 06:16:51.353217 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000009 (ops 42-46)
I20260812 06:16:51.353245 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000010 (ops 47-51)
I20260812 06:16:51.353286 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000011 (ops 52-56)
I20260812 06:16:51.353310 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000012 (ops 57-60)
I20260812 06:16:51.353336 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000013 (ops 61-65)
I20260812 06:16:51.383494 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: LogGCOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:51.384107 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling UndoDeltaBlockGCOp(5561da7ca4624576a5459f470a9f1f91): 462 bytes on disk
I20260812 06:16:51.384807 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: UndoDeltaBlockGCOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:16:51.385303 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:51.428208 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.043s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4667,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.428969 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling LogGCOp(5561da7ca4624576a5459f470a9f1f91): free 12017932 bytes of WAL
I20260812 06:16:51.429221 10985 log_reader.cc:385] T 5561da7ca4624576a5459f470a9f1f91: removed 1 log segments from log reader
I20260812 06:16:51.429339 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000014 (ops 66-70)
I20260812 06:16:51.432670 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: LogGCOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:51.433104 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:51.514530 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.081s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5290,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.515187 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:51.616417 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.101s	user 0.013s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12448,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:51.617156 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:51.716327 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.099s	user 0.018s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9203,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:51.717036 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=7.149875
I20260812 06:16:51.815196 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.098s	user 0.013s	sys 0.011s Metrics: {"bytes_written":9107614,"delete_count":0,"lbm_write_time_us":11046,"lbm_writes_lt_1ms":225,"reinsert_count":0,"update_count":1110}
I20260812 06:16:51.815727 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=9.134250
I20260812 06:16:51.916250 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.100s	user 0.025s	sys 0.009s Metrics: {"bytes_written":11363943,"delete_count":0,"lbm_write_time_us":15201,"lbm_writes_lt_1ms":280,"reinsert_count":0,"update_count":1385}
I20260812 06:16:51.917025 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:52.011176 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.094s	user 0.013s	sys 0.012s Metrics: {"bytes_written":8246106,"delete_count":0,"lbm_write_time_us":10975,"lbm_writes_lt_1ms":204,"reinsert_count":0,"update_count":1005}
I20260812 06:16:52.012117 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=7.149875
I20260812 06:16:52.113844 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.102s	user 0.015s	sys 0.005s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":8937,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:52.114506 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:52.216568 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.102s	user 0.010s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10587,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:52.217303 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=10.126437
I20260812 06:16:52.319175 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.102s	user 0.016s	sys 0.020s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":14875,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:52.319941 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:52.418617 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.098s	user 0.014s	sys 0.007s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":9233,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:52.419358 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=8.142062
I20260812 06:16:52.520925 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.101s	user 0.016s	sys 0.013s Metrics: {"bytes_written":9599901,"delete_count":0,"lbm_write_time_us":12584,"lbm_writes_lt_1ms":237,"reinsert_count":0,"update_count":1170}
I20260812 06:16:52.521481 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=9.134250
I20260812 06:16:52.620057 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.098s	user 0.026s	sys 0.009s Metrics: {"bytes_written":10912679,"delete_count":0,"lbm_write_time_us":15576,"lbm_writes_lt_1ms":269,"reinsert_count":0,"update_count":1330}
I20260812 06:16:52.620606 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:52.724928 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.104s	user 0.011s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8663,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:52.726351 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:52.830384 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.104s	user 0.022s	sys 0.007s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":12935,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:52.831238 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=7.149875
I20260812 06:16:52.931344 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.100s	user 0.015s	sys 0.005s Metrics: {"bytes_written":8615325,"delete_count":0,"lbm_write_time_us":9085,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:52.932101 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=10.126437
I20260812 06:16:53.028167 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.096s	user 0.020s	sys 0.017s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":16388,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:53.028950 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:53.130120 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.101s	user 0.020s	sys 0.004s Metrics: {"bytes_written":8205080,"delete_count":0,"lbm_write_time_us":10449,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:53.130935 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:53.233068 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.101s	user 0.016s	sys 0.013s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12948,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:53.234527 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=8.142062
I20260812 06:16:53.336503 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.102s	user 0.019s	sys 0.008s Metrics: {"bytes_written":9558873,"delete_count":0,"lbm_write_time_us":11006,"lbm_writes_lt_1ms":236,"reinsert_count":0,"update_count":1165}
I20260812 06:16:53.338658 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=9.134250
I20260812 06:16:53.441828 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.103s	user 0.021s	sys 0.010s Metrics: {"bytes_written":10953703,"delete_count":0,"lbm_write_time_us":13126,"lbm_writes_lt_1ms":270,"reinsert_count":0,"update_count":1335}
I20260812 06:16:53.442711 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=7.149875
I20260812 06:16:53.542477 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.100s	user 0.012s	sys 0.010s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9639,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:53.543087 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=8.142062
I20260812 06:16:53.643126 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.100s	user 0.019s	sys 0.006s Metrics: {"bytes_written":10010139,"delete_count":0,"lbm_write_time_us":11026,"lbm_writes_lt_1ms":247,"reinsert_count":0,"update_count":1220}
I20260812 06:16:53.643788 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=8.142062
I20260812 06:16:53.740715 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.097s	user 0.026s	sys 0.004s Metrics: {"bytes_written":10092196,"delete_count":0,"lbm_write_time_us":12725,"lbm_writes_lt_1ms":249,"reinsert_count":0,"update_count":1230}
I20260812 06:16:53.741544 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:53.841431 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.100s	user 0.016s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8635,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:53.842278 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=8.142062
I20260812 06:16:53.941088 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.099s	user 0.013s	sys 0.012s Metrics: {"bytes_written":9805021,"delete_count":0,"lbm_write_time_us":11481,"lbm_writes_lt_1ms":242,"reinsert_count":0,"update_count":1195}
I20260812 06:16:53.941787 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=8.142062
I20260812 06:16:54.037382 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.095s	user 0.018s	sys 0.009s Metrics: {"bytes_written":10174241,"delete_count":0,"lbm_write_time_us":11981,"lbm_writes_lt_1ms":251,"reinsert_count":0,"update_count":1240}
I20260812 06:16:54.037988 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=7.149875
I20260812 06:16:54.078962 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.041s	user 0.023s	sys 0.003s Metrics: {"bytes_written":8738399,"delete_count":0,"lbm_write_time_us":12936,"lbm_writes_lt_1ms":216,"reinsert_count":0,"update_count":1065}
I20260812 06:16:54.079623 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:54.091504 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.092129 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushMRSOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.195565
I20260812 06:16:54.122834 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushMRSOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":2545869,"cfile_init":1,"dirs.queue_time_us":238,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":809,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2757,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":62,"thread_start_us":131,"threads_started":1}
I20260812 06:16:54.123687 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling LogGCOp(5561da7ca4624576a5459f470a9f1f91): free 249874149 bytes of WAL
I20260812 06:16:54.123946 10985 log_reader.cc:385] T 5561da7ca4624576a5459f470a9f1f91: removed 25 log segments from log reader
I20260812 06:16:54.123991 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000015 (ops 71-75)
I20260812 06:16:54.124025 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000016 (ops 76-80)
I20260812 06:16:54.124090 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000017 (ops 81-85)
I20260812 06:16:54.124158 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000018 (ops 86-90)
I20260812 06:16:54.124205 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000019 (ops 91-94)
I20260812 06:16:54.124239 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000020 (ops 95-99)
I20260812 06:16:54.124281 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000021 (ops 100-104)
I20260812 06:16:54.124321 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000022 (ops 105-109)
I20260812 06:16:54.124373 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000023 (ops 110-114)
I20260812 06:16:54.124408 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000024 (ops 115-118)
I20260812 06:16:54.124471 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000025 (ops 119-123)
I20260812 06:16:54.124516 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000026 (ops 124-128)
I20260812 06:16:54.124557 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000027 (ops 129-133)
I20260812 06:16:54.124598 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000028 (ops 134-138)
I20260812 06:16:54.124637 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000029 (ops 139-143)
I20260812 06:16:54.124677 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000030 (ops 144-148)
I20260812 06:16:54.124717 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000031 (ops 149-152)
I20260812 06:16:54.124758 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000032 (ops 153-157)
I20260812 06:16:54.124797 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000033 (ops 158-162)
I20260812 06:16:54.124836 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000034 (ops 163-166)
I20260812 06:16:54.124879 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000035 (ops 167-171)
I20260812 06:16:54.124922 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000036 (ops 172-176)
I20260812 06:16:54.124961 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000037 (ops 177-181)
I20260812 06:16:54.125001 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000038 (ops 182-186)
I20260812 06:16:54.125041 10985 log.cc:1079] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: Deleting log segment in path: /tmp/dist-test-taskGrm2z6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515403991667-10495-0/minicluster-data/ts-0-root/wals/5561da7ca4624576a5459f470a9f1f91/wal-000000039 (ops 187-191)
I20260812 06:16:54.184186 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: LogGCOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.060s	user 0.000s	sys 0.059s Metrics: {}
I20260812 06:16:54.184674 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=6.157687
I20260812 06:16:54.217119 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.032s	user 0.018s	sys 0.001s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8725,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:54.217584 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling UndoDeltaBlockGCOp(5561da7ca4624576a5459f470a9f1f91): 834 bytes on disk
I20260812 06:16:54.218014 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: UndoDeltaBlockGCOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:16:54.218505 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91): perf score=2.188937
I20260812 06:16:54.229864 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: FlushDeltaMemStoresOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.230468 11082 maintenance_manager.cc:419] P 8ed12603a4b846cda81861fb4cd65de6: Scheduling MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91): perf score=1.000000
I20260812 06:16:54.313890 10495 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.553s	user 1.730s	sys 0.112s
W20260812 06:16:55.186076 10495 scanner-internal.cc:458] Time spent opening tablet: real 0.872s	user 0.001s	sys 0.000s
I20260812 06:16:55.188339 10495 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.874s	user 0.002s	sys 0.000s
I20260812 06:16:55.188843 10495 tablet_server.cc:179] TabletServer@127.10.63.193:0 shutting down...
I20260812 06:16:56.206251 10985 maintenance_manager.cc:643] P 8ed12603a4b846cda81861fb4cd65de6: MajorDeltaCompactionOp(5561da7ca4624576a5459f470a9f1f91) complete. Timing: real 1.976s	user 1.006s	sys 0.963s Metrics: {"cfile_cache_miss":7064,"cfile_cache_miss_bytes":291435357,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":34,"delta_iterators_relevant":34,"dirs.queue_time_us":1734,"lbm_read_time_us":109807,"lbm_reads_lt_1ms":7100,"lbm_write_time_us":321853,"lbm_writes_lt_1ms":7048,"mutex_wait_us":65,"peak_mem_usage":870843080,"reinsert_count":0,"spinlock_wait_cycles":988032,"thread_start_us":744,"threads_started":9,"update_count":35000,"wal-append.queue_time_us":284}
I20260812 06:16:56.206945 10495 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:56.207181 10495 tablet_replica.cc:333] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6: stopping tablet replica
I20260812 06:16:56.207343 10495 raft_consensus.cc:2243] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:56.207547 10495 raft_consensus.cc:2272] T 5561da7ca4624576a5459f470a9f1f91 P 8ed12603a4b846cda81861fb4cd65de6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:56.223712 10495 tablet_server.cc:196] TabletServer@127.10.63.193:0 shutdown complete.
I20260812 06:16:57.325709 10495 master.cc:562] Master@127.10.63.254:33389 shutting down...
I20260812 06:16:57.329277 10495 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:57.329504 10495 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:57.329612 10495 tablet_replica.cc:333] T 00000000000000000000000000000000 P 20cd321cbfb64dc09192abf63c3630dd: stopping tablet replica
I20260812 06:16:57.342517 10495 master.cc:584] Master@127.10.63.254:33389 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (7905 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (13430 ms total)

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