[==========] 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:34.375468 13805 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.123.126:42871
I20260812 06:16:34.376580 13805 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:34.377314 13805 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:34.384728 13819 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:34.384790 13814 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:34.385097 13817 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:34.385083 13805 server_base.cc:1061] running on GCE node
I20260812 06:16:34.385766 13805 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:34.385864 13805 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:34.385891 13805 hybrid_clock.cc:648] HybridClock initialized: now 1786515394385890 us; error 0 us; skew 500 ppm
I20260812 06:16:34.387925 13805 webserver.cc:533] Webserver started at http://127.13.123.126:45663/ using document root <none> and password file <none>
I20260812 06:16:34.388520 13805 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:34.388588 13805 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:34.388803 13805 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:34.390666 13805 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/master-0-root/instance:
uuid: "1596a501ca314f00a090fb3d1138015c"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-z8x9"
I20260812 06:16:34.395056 13805 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:16:34.398128 13829 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:34.399551 13805 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:34.399753 13805 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/master-0-root
uuid: "1596a501ca314f00a090fb3d1138015c"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-z8x9"
I20260812 06:16:34.399900 13805 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-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:34.438759 13805 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:34.439499 13805 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:34.439653 13805 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:34.448107 13805 rpc_server.cc:307] RPC server started. Bound to: 127.13.123.126:42871
I20260812 06:16:34.448176 13951 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.123.126:42871 every 8 connection(s)
I20260812 06:16:34.450650 13954 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:34.456375 13954 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c: Bootstrap starting.
I20260812 06:16:34.458985 13954 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:34.460268 13954 log.cc:826] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:34.462651 13954 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c: No bootstrap required, opened a new log
I20260812 06:16:34.466109 13954 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1596a501ca314f00a090fb3d1138015c" member_type: VOTER }
I20260812 06:16:34.466333 13954 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:34.466413 13954 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1596a501ca314f00a090fb3d1138015c, State: Initialized, Role: FOLLOWER
I20260812 06:16:34.467144 13954 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [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: "1596a501ca314f00a090fb3d1138015c" member_type: VOTER }
I20260812 06:16:34.467331 13954 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:34.467412 13954 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:34.467545 13954 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:34.468954 13954 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1596a501ca314f00a090fb3d1138015c" member_type: VOTER }
I20260812 06:16:34.469589 13954 leader_election.cc:304] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [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: 1596a501ca314f00a090fb3d1138015c; no voters: 
I20260812 06:16:34.469964 13954 leader_election.cc:290] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:34.470201 13957 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:34.470510 13957 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 1 LEADER]: Becoming Leader. State: Replica: 1596a501ca314f00a090fb3d1138015c, State: Running, Role: LEADER
I20260812 06:16:34.471045 13957 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [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: "1596a501ca314f00a090fb3d1138015c" member_type: VOTER }
I20260812 06:16:34.471194 13954 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:34.473451 13959 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1596a501ca314f00a090fb3d1138015c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1596a501ca314f00a090fb3d1138015c" member_type: VOTER } }
I20260812 06:16:34.473590 13959 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:34.473701 13805 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:34.473843 13960 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1596a501ca314f00a090fb3d1138015c. Latest consensus state: current_term: 1 leader_uuid: "1596a501ca314f00a090fb3d1138015c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1596a501ca314f00a090fb3d1138015c" member_type: VOTER } }
I20260812 06:16:34.473920 13960 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [sys.catalog]: This master's current role is: LEADER
W20260812 06:16:34.476137 13996 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:34.476225 13996 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:34.476347 13998 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:34.477300 13998 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:34.482108 13998 catalog_manager.cc:1383] Generated new cluster ID: afdb6b9bba2c412caccfdd9d56eed29d
I20260812 06:16:34.482194 13998 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:34.487403 13998 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:34.488616 13998 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:34.510152 13998 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c: Generated new TSK 0
I20260812 06:16:34.511040 13998 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:34.538715 13805 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:34.541632 14007 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:34.541738 14008 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:34.541749 14012 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:34.542163 13805 server_base.cc:1061] running on GCE node
I20260812 06:16:34.542356 13805 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:34.542405 13805 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:34.542428 13805 hybrid_clock.cc:648] HybridClock initialized: now 1786515394542429 us; error 0 us; skew 500 ppm
I20260812 06:16:34.543478 13805 webserver.cc:533] Webserver started at http://127.13.123.65:41057/ using document root <none> and password file <none>
I20260812 06:16:34.543666 13805 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:34.543730 13805 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:34.543821 13805 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:34.544283 13805 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/instance:
uuid: "15f3330e056d4018a3d0e4f9a8d54e7d"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-z8x9"
I20260812 06:16:34.546309 13805 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:16:34.548408 14022 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:34.548738 13805 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:16:34.548869 13805 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root
uuid: "15f3330e056d4018a3d0e4f9a8d54e7d"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-z8x9"
I20260812 06:16:34.548972 13805 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-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:34.574328 13805 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:34.575206 13805 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:34.575766 13805 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:34.576717 13805 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:34.576807 13805 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:34.576907 13805 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:34.576958 13805 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:34.584262 13805 rpc_server.cc:307] RPC server started. Bound to: 127.13.123.65:44751
I20260812 06:16:34.584445 14126 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.123.65:44751 every 8 connection(s)
I20260812 06:16:34.598871 14127 heartbeater.cc:344] Connected to a master server at 127.13.123.126:42871
I20260812 06:16:34.599162 14127 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:34.599656 14127 heartbeater.cc:507] Master 127.13.123.126:42871 requested a full tablet report, sending...
I20260812 06:16:34.601126 13863 ts_manager.cc:194] Registered new tserver with Master: 15f3330e056d4018a3d0e4f9a8d54e7d (127.13.123.65:44751)
I20260812 06:16:34.602003 13805 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016990461s
I20260812 06:16:34.602413 13863 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58292
I20260812 06:16:34.612717 13863 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58302:
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:34.630517 14066 tablet_service.cc:1511] Processing CreateTablet for tablet 5f1503d9b65e4487842dadde89a897e8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d02478871311473d9e0cb2aae8ec5376]), partition=
I20260812 06:16:34.631031 14066 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5f1503d9b65e4487842dadde89a897e8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:34.634022 14162 tablet_bootstrap.cc:492] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Bootstrap starting.
I20260812 06:16:34.637146 14162 tablet_bootstrap.cc:654] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:34.639779 14162 tablet_bootstrap.cc:492] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: No bootstrap required, opened a new log
I20260812 06:16:34.639911 14162 ts_tablet_manager.cc:1403] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Time spent bootstrapping tablet: real 0.006s	user 0.002s	sys 0.003s
I20260812 06:16:34.641165 14162 raft_consensus.cc:359] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15f3330e056d4018a3d0e4f9a8d54e7d" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44751 } }
I20260812 06:16:34.641347 14162 raft_consensus.cc:385] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:34.641396 14162 raft_consensus.cc:740] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 15f3330e056d4018a3d0e4f9a8d54e7d, State: Initialized, Role: FOLLOWER
I20260812 06:16:34.641543 14162 consensus_queue.cc:260] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [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: "15f3330e056d4018a3d0e4f9a8d54e7d" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44751 } }
I20260812 06:16:34.641655 14162 raft_consensus.cc:399] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:34.641706 14162 raft_consensus.cc:493] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:34.641760 14162 raft_consensus.cc:3060] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:34.643647 14162 raft_consensus.cc:515] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15f3330e056d4018a3d0e4f9a8d54e7d" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44751 } }
I20260812 06:16:34.643813 14162 leader_election.cc:304] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [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: 15f3330e056d4018a3d0e4f9a8d54e7d; no voters: 
I20260812 06:16:34.644287 14162 leader_election.cc:290] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:34.644543 14165 raft_consensus.cc:2804] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:34.644855 14165 raft_consensus.cc:697] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 1 LEADER]: Becoming Leader. State: Replica: 15f3330e056d4018a3d0e4f9a8d54e7d, State: Running, Role: LEADER
I20260812 06:16:34.644944 14162 ts_tablet_manager.cc:1434] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Time spent starting tablet: real 0.005s	user 0.003s	sys 0.002s
I20260812 06:16:34.645292 14127 heartbeater.cc:499] Master 127.13.123.126:42871 was elected leader, sending a full tablet report...
I20260812 06:16:34.645077 14165 consensus_queue.cc:237] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [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: "15f3330e056d4018a3d0e4f9a8d54e7d" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44751 } }
I20260812 06:16:34.648661 13863 catalog_manager.cc:5719] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d reported cstate change: term changed from 0 to 1, leader changed from <none> to 15f3330e056d4018a3d0e4f9a8d54e7d (127.13.123.65). New cstate: current_term: 1 leader_uuid: "15f3330e056d4018a3d0e4f9a8d54e7d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15f3330e056d4018a3d0e4f9a8d54e7d" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44751 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:34.721361 13805 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.013s	sys 0.018s
I20260812 06:16:34.835573 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushMRSOp(5f1503d9b65e4487842dadde89a897e8): perf score=15.086190
I20260812 06:16:35.002039 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushMRSOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.166s	user 0.133s	sys 0.032s Metrics: {"bytes_written":12307493,"cfile_init":1,"compiler_manager_pool.queue_time_us":191,"delete_count":0,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1126,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43322,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":121,"threads_started":1,"update_count":1500}
I20260812 06:16:35.003422 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling LogGCOp(5f1503d9b65e4487842dadde89a897e8): free 8725963 bytes of WAL
I20260812 06:16:35.003850 14032 log_reader.cc:385] T 5f1503d9b65e4487842dadde89a897e8: removed 1 log segments from log reader
I20260812 06:16:35.003947 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000001 (ops 1-6)
I20260812 06:16:35.006457 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: LogGCOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:35.006845 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:35.026582 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.020s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5610,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.027202 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling UndoDeltaBlockGCOp(5f1503d9b65e4487842dadde89a897e8): 12308958 bytes on disk
I20260812 06:16:35.027957 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: UndoDeltaBlockGCOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:16:35.028419 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:35.179816 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.151s	user 0.121s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":563,"lbm_read_time_us":9120,"lbm_reads_lt_1ms":460,"lbm_write_time_us":29868,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":335,"threads_started":5,"update_count":2000}
I20260812 06:16:35.180416 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:35.230201 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.050s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16528,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.230736 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:35.241816 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.242497 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:35.380107 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.137s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1598,"lbm_read_time_us":7497,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29849,"lbm_writes_lt_1ms":443,"mutex_wait_us":164,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":613248,"update_count":2000}
I20260812 06:16:35.380776 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:35.415319 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14725,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.416050 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:35.532483 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.116s	user 0.094s	sys 0.019s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":263,"lbm_read_time_us":7708,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23276,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":26112,"update_count":1500}
I20260812 06:16:35.532982 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:35.583627 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.050s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18062,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.584192 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:35.598419 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.599051 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:35.733839 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.135s	user 0.106s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":257,"lbm_read_time_us":9509,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25881,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":34560,"update_count":2000}
I20260812 06:16:35.734419 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:35.786336 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.052s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18587,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.786901 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:35.797891 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.798671 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:35.933692 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.135s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":243,"lbm_read_time_us":10586,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27806,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":38144,"update_count":2000}
I20260812 06:16:35.934253 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:35.984743 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.050s	user 0.013s	sys 0.028s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18569,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.985358 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:35.996282 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.997057 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:36.136191 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.139s	user 0.083s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":9793,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30582,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:16:36.137159 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:36.188967 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.052s	user 0.020s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19207,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:36.189683 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:36.204324 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.014s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5378,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.205245 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:36.361486 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.156s	user 0.103s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":898,"lbm_read_time_us":16140,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":471,"lbm_write_time_us":25568,"lbm_writes_lt_1ms":443,"mutex_wait_us":591,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:16:36.362543 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:36.417061 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.054s	user 0.021s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":26638,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:36.417953 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:36.429471 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.430037 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushMRSOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:36.464126 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushMRSOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":561,"dirs.run_wall_time_us":1842,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1429,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:36.465847 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling LogGCOp(5f1503d9b65e4487842dadde89a897e8): free 136275161 bytes of WAL
I20260812 06:16:36.466337 14032 log_reader.cc:385] T 5f1503d9b65e4487842dadde89a897e8: removed 13 log segments from log reader
I20260812 06:16:36.466429 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000002 (ops 7-11)
I20260812 06:16:36.466490 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000003 (ops 12-16)
I20260812 06:16:36.466743 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000004 (ops 17-20)
I20260812 06:16:36.466816 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000005 (ops 21-25)
I20260812 06:16:36.466861 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000006 (ops 26-30)
I20260812 06:16:36.466918 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000007 (ops 31-35)
I20260812 06:16:36.466961 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000008 (ops 36-40)
I20260812 06:16:36.467000 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000009 (ops 41-45)
I20260812 06:16:36.467039 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000010 (ops 46-50)
I20260812 06:16:36.467078 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000011 (ops 51-55)
I20260812 06:16:36.467115 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000012 (ops 56-60)
I20260812 06:16:36.467155 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000013 (ops 61-65)
I20260812 06:16:36.467195 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000014 (ops 66-70)
I20260812 06:16:36.499864 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: LogGCOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.034s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:16:36.500701 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling UndoDeltaBlockGCOp(5f1503d9b65e4487842dadde89a897e8): 483 bytes on disk
I20260812 06:16:36.501468 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: UndoDeltaBlockGCOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4}
I20260812 06:16:36.502139 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=3.181125
I20260812 06:16:36.526427 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.024s	user 0.004s	sys 0.019s Metrics: {"bytes_written":4964170,"delete_count":0,"lbm_write_time_us":5711,"lbm_writes_lt_1ms":124,"reinsert_count":0,"update_count":605}
I20260812 06:16:36.527117 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:36.540550 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":4686,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:16:36.541142 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:36.749559 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.208s	user 0.144s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836355,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2288,"lbm_read_time_us":13907,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35517,"lbm_writes_lt_1ms":643,"mutex_wait_us":1280,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":57216,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:16:36.750965 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=14.095187
I20260812 06:16:36.817883 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.066s	user 0.046s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24280,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:36.818552 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:36.830267 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.830808 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:37.015973 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.185s	user 0.117s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":898,"lbm_read_time_us":13107,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31361,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:16:37.016776 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:37.060176 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.043s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18321,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:37.060972 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:37.073720 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.074213 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:37.220670 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.146s	user 0.107s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1573,"lbm_read_time_us":9232,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26982,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":454,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:37.221485 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:37.272970 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.051s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18436,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:37.273631 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:37.286032 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.287217 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:37.430227 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.142s	user 0.122s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":586,"lbm_read_time_us":10545,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32173,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":55296,"update_count":2000}
I20260812 06:16:37.431277 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:37.479260 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.047s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22148,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:37.479861 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:37.496246 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.497082 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:37.632280 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.135s	user 0.102s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":507,"lbm_read_time_us":9950,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31204,"lbm_writes_lt_1ms":443,"mutex_wait_us":119,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:37.633062 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:37.688154 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.055s	user 0.033s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17841,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:37.688807 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:37.700690 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4630,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.701256 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:37.881337 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.180s	user 0.127s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1287,"lbm_read_time_us":12991,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31340,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":370,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:37.882372 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:37.938151 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.056s	user 0.026s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21803,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:37.938743 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:37.952909 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.014s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.953431 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:38.092155 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.139s	user 0.109s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1027,"lbm_read_time_us":10099,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28844,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.093119 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=10.126437
I20260812 06:16:38.147761 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.054s	user 0.023s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18866,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.148559 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:38.163081 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5547,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.163926 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushMRSOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:38.198627 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushMRSOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":315,"dirs.run_wall_time_us":1920,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1803,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:38.199522 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling LogGCOp(5f1503d9b65e4487842dadde89a897e8): free 129320528 bytes of WAL
I20260812 06:16:38.199810 14032 log_reader.cc:385] T 5f1503d9b65e4487842dadde89a897e8: removed 13 log segments from log reader
I20260812 06:16:38.199872 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000015 (ops 71-75)
I20260812 06:16:38.199903 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000016 (ops 76-80)
I20260812 06:16:38.199965 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000017 (ops 81-84)
I20260812 06:16:38.200016 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000018 (ops 85-89)
I20260812 06:16:38.200035 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000019 (ops 90-94)
I20260812 06:16:38.200052 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000020 (ops 95-99)
I20260812 06:16:38.200069 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000021 (ops 100-104)
I20260812 06:16:38.200085 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000022 (ops 105-108)
I20260812 06:16:38.200103 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000023 (ops 109-113)
I20260812 06:16:38.200120 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000024 (ops 114-118)
I20260812 06:16:38.200137 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000025 (ops 119-123)
I20260812 06:16:38.200155 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000026 (ops 124-128)
I20260812 06:16:38.200243 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000027 (ops 129-133)
I20260812 06:16:38.230350 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: LogGCOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:38.230926 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=3.181125
I20260812 06:16:38.246840 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4800077,"delete_count":0,"lbm_write_time_us":6289,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:16:38.247380 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:38.261672 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3405230,"delete_count":0,"lbm_write_time_us":4909,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:16:38.262322 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling UndoDeltaBlockGCOp(5f1503d9b65e4487842dadde89a897e8): 483 bytes on disk
I20260812 06:16:38.263022 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: UndoDeltaBlockGCOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4}
I20260812 06:16:38.263878 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:38.449129 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.185s	user 0.147s	sys 0.029s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":547,"lbm_read_time_us":14195,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34638,"lbm_writes_lt_1ms":643,"mutex_wait_us":68,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:16:38.449826 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=14.095187
I20260812 06:16:38.509429 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.059s	user 0.022s	sys 0.035s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26344,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.509953 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:38.521742 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.522414 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:38.695194 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.173s	user 0.134s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":13055,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32290,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:16:38.695765 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=14.095187
I20260812 06:16:38.767560 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.072s	user 0.022s	sys 0.033s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25463,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.768132 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:38.778990 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.779749 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:38.986161 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.206s	user 0.112s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1697,"lbm_read_time_us":11775,"lbm_reads_lt_1ms":572,"lbm_write_time_us":40342,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":540,"mutex_wait_us":395,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:16:38.988691 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=12.110812
I20260812 06:16:39.033731 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.045s	user 0.037s	sys 0.008s Metrics: {"bytes_written":13620264,"delete_count":0,"lbm_write_time_us":18840,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:16:39.034683 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.196750
I20260812 06:16:39.053522 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.019s	user 0.011s	sys 0.003s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":5044,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:16:39.054354 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:39.228964 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.174s	user 0.120s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631282,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1349,"lbm_read_time_us":8402,"lbm_reads_lt_1ms":464,"lbm_write_time_us":39474,"lbm_writes_lt_1ms":443,"mutex_wait_us":372,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:16:39.229626 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=14.095187
I20260812 06:16:39.280844 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.051s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23118,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.281522 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:39.307888 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.026s	user 0.009s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5875,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.308523 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:39.496670 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.188s	user 0.122s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1766,"lbm_read_time_us":13027,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33015,"lbm_writes_lt_1ms":543,"mutex_wait_us":486,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:16:39.497762 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=11.118625
I20260812 06:16:39.537333 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.039s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17278,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:39.538188 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:39.564760 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5243,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.565543 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:39.578481 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4539,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.579206 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:39.777361 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.198s	user 0.133s	sys 0.058s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":733,"lbm_read_time_us":12882,"lbm_reads_lt_1ms":573,"lbm_write_time_us":41337,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:16:39.778249 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=11.118625
I20260812 06:16:39.822149 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.044s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20729,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:39.822795 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=2.188937
I20260812 06:16:39.838935 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.016s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6958,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.839479 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushMRSOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:39.874042 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushMRSOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1593,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2081,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":2304}
I20260812 06:16:39.874814 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling LogGCOp(5f1503d9b65e4487842dadde89a897e8): free 124710577 bytes of WAL
I20260812 06:16:39.875053 14032 log_reader.cc:385] T 5f1503d9b65e4487842dadde89a897e8: removed 12 log segments from log reader
I20260812 06:16:39.875098 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000028 (ops 134-138)
I20260812 06:16:39.875128 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000029 (ops 139-143)
I20260812 06:16:39.875144 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000030 (ops 144-148)
I20260812 06:16:39.875208 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000031 (ops 149-153)
I20260812 06:16:39.875253 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000032 (ops 154-158)
I20260812 06:16:39.875319 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000033 (ops 159-163)
I20260812 06:16:39.875362 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000034 (ops 164-168)
I20260812 06:16:39.875404 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000035 (ops 169-173)
I20260812 06:16:39.875440 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000036 (ops 174-178)
I20260812 06:16:39.875486 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000037 (ops 179-183)
I20260812 06:16:39.875527 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000038 (ops 184-188)
I20260812 06:16:39.875563 14032 log.cc:1079] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/5f1503d9b65e4487842dadde89a897e8/wal-000000039 (ops 189-193)
I20260812 06:16:39.910082 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: LogGCOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.035s	user 0.003s	sys 0.031s Metrics: {}
I20260812 06:16:39.910698 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=5.165500
I20260812 06:16:39.936211 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.025s	user 0.018s	sys 0.004s Metrics: {"bytes_written":7097423,"delete_count":0,"lbm_write_time_us":10215,"lbm_writes_lt_1ms":176,"reinsert_count":0,"update_count":865}
I20260812 06:16:39.937079 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling UndoDeltaBlockGCOp(5f1503d9b65e4487842dadde89a897e8): 482 bytes on disk
I20260812 06:16:39.937879 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: UndoDeltaBlockGCOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.938642 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:40.097667 13805 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.376s	user 1.946s	sys 0.151s
I20260812 06:16:40.143497 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.205s	user 0.134s	sys 0.065s Metrics: {"cfile_cache_miss":606,"cfile_cache_miss_bytes":27728592,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"lbm_read_time_us":13663,"lbm_reads_lt_1ms":638,"lbm_write_time_us":35529,"lbm_writes_lt_1ms":616,"peak_mem_usage":71313375,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2865}
I20260812 06:16:40.144093 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8): perf score=11.118625
I20260812 06:16:40.183539 13805 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.085s	user 0.002s	sys 0.003s
I20260812 06:16:40.186617 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: FlushDeltaMemStoresOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.042s	user 0.024s	sys 0.016s Metrics: {"bytes_written":13415147,"delete_count":0,"lbm_write_time_us":19011,"lbm_writes_lt_1ms":330,"reinsert_count":0,"update_count":1635}
I20260812 06:16:40.187570 14130 maintenance_manager.cc:419] P 15f3330e056d4018a3d0e4f9a8d54e7d: Scheduling MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8): perf score=1.000000
I20260812 06:16:40.188481 13805 tablet_server.cc:179] TabletServer@127.13.123.65:0 shutting down...
I20260812 06:16:40.294128 14032 maintenance_manager.cc:643] P 15f3330e056d4018a3d0e4f9a8d54e7d: MajorDeltaCompactionOp(5f1503d9b65e4487842dadde89a897e8) complete. Timing: real 0.106s	user 0.090s	sys 0.016s Metrics: {"cfile_cache_miss":358,"cfile_cache_miss_bytes":17636438,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":762,"lbm_read_time_us":8132,"lbm_reads_lt_1ms":394,"lbm_write_time_us":20173,"lbm_writes_lt_1ms":370,"mutex_wait_us":140,"peak_mem_usage":41451469,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":1635}
I20260812 06:16:40.295063 13805 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:40.295620 13805 tablet_replica.cc:333] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d: stopping tablet replica
I20260812 06:16:40.295969 13805 raft_consensus.cc:2243] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:40.296253 13805 raft_consensus.cc:2272] T 5f1503d9b65e4487842dadde89a897e8 P 15f3330e056d4018a3d0e4f9a8d54e7d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:40.315097 13805 tablet_server.cc:196] TabletServer@127.13.123.65:0 shutdown complete.
I20260812 06:16:40.327687 13805 master.cc:562] Master@127.13.123.126:42871 shutting down...
I20260812 06:16:40.332171 13805 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:40.332480 13805 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:40.332566 13805 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1596a501ca314f00a090fb3d1138015c: stopping tablet replica
I20260812 06:16:40.346518 13805 master.cc:584] Master@127.13.123.126:42871 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6066 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:40.441783 13805 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.123.126:35001
I20260812 06:16:40.442147 13805 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:40.445111 13805 server_base.cc:1061] running on GCE node
W20260812 06:16:40.445149 14214 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:40.445278 14201 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:40.445274 14208 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:40.445659 13805 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.445730 13805 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:40.445755 13805 hybrid_clock.cc:648] HybridClock initialized: now 1786515400445755 us; error 0 us; skew 500 ppm
I20260812 06:16:40.446753 13805 webserver.cc:533] Webserver started at http://127.13.123.126:36401/ using document root <none> and password file <none>
I20260812 06:16:40.446965 13805 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.447038 13805 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.447125 13805 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.447547 13805 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/master-0-root/instance:
uuid: "5e05f9cf6d304b64951a9d73f7de7f98"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-z8x9"
I20260812 06:16:40.450415 13805 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:40.451649 14221 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:40.452096 13805 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:40.452214 13805 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/master-0-root
uuid: "5e05f9cf6d304b64951a9d73f7de7f98"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-z8x9"
I20260812 06:16:40.452322 13805 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-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:40.481630 13805 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.482267 13805 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.487474 13805 rpc_server.cc:307] RPC server started. Bound to: 127.13.123.126:35001
I20260812 06:16:40.489848 14317 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.123.126:35001 every 8 connection(s)
I20260812 06:16:40.490638 14318 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:40.502841 14318 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98: Bootstrap starting.
I20260812 06:16:40.503708 14318 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.504930 14318 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98: No bootstrap required, opened a new log
I20260812 06:16:40.505369 14318 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e05f9cf6d304b64951a9d73f7de7f98" member_type: VOTER }
I20260812 06:16:40.505463 14318 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.505487 14318 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5e05f9cf6d304b64951a9d73f7de7f98, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.505661 14318 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [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: "5e05f9cf6d304b64951a9d73f7de7f98" member_type: VOTER }
I20260812 06:16:40.505757 14318 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.505784 14318 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.505815 14318 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.506564 14318 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e05f9cf6d304b64951a9d73f7de7f98" member_type: VOTER }
I20260812 06:16:40.506692 14318 leader_election.cc:304] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [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: 5e05f9cf6d304b64951a9d73f7de7f98; no voters: 
I20260812 06:16:40.506865 14318 leader_election.cc:290] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.507035 14322 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.507238 14322 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 1 LEADER]: Becoming Leader. State: Replica: 5e05f9cf6d304b64951a9d73f7de7f98, State: Running, Role: LEADER
I20260812 06:16:40.507392 14318 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:40.507423 14322 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [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: "5e05f9cf6d304b64951a9d73f7de7f98" member_type: VOTER }
I20260812 06:16:40.507867 14327 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5e05f9cf6d304b64951a9d73f7de7f98. Latest consensus state: current_term: 1 leader_uuid: "5e05f9cf6d304b64951a9d73f7de7f98" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e05f9cf6d304b64951a9d73f7de7f98" member_type: VOTER } }
I20260812 06:16:40.507962 14327 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.507850 14324 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5e05f9cf6d304b64951a9d73f7de7f98" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e05f9cf6d304b64951a9d73f7de7f98" member_type: VOTER } }
I20260812 06:16:40.508026 14324 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.508237 14334 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:40.509063 14334 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:40.509426 13805 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:40.511482 14334 catalog_manager.cc:1383] Generated new cluster ID: 7473df0a9e874f48a990962dac33d2fd
I20260812 06:16:40.511560 14334 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:40.519806 14334 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:40.520473 14334 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:40.526511 14334 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98: Generated new TSK 0
I20260812 06:16:40.526778 14334 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:40.542225 13805 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:40.545529 13805 server_base.cc:1061] running on GCE node
W20260812 06:16:40.545714 14367 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:40.545868 14362 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:40.546231 14365 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:40.546649 13805 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.546734 13805 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:40.546751 13805 hybrid_clock.cc:648] HybridClock initialized: now 1786515400546751 us; error 0 us; skew 500 ppm
I20260812 06:16:40.547830 13805 webserver.cc:533] Webserver started at http://127.13.123.65:44363/ using document root <none> and password file <none>
I20260812 06:16:40.548025 13805 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.548077 13805 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.548166 13805 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.548642 13805 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/instance:
uuid: "cc555f4a2ec24ed98eee3a0be6757aeb"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-z8x9"
I20260812 06:16:40.550632 13805 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:40.551942 14376 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:40.552441 13805 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:40.552584 13805 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root
uuid: "cc555f4a2ec24ed98eee3a0be6757aeb"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-z8x9"
I20260812 06:16:40.552702 13805 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-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:40.579370 13805 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.580243 13805 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.580861 13805 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:40.581641 13805 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:40.581714 13805 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.581779 13805 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:40.581837 13805 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.587129 13805 rpc_server.cc:307] RPC server started. Bound to: 127.13.123.65:44009
I20260812 06:16:40.587877 14499 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.123.65:44009 every 8 connection(s)
I20260812 06:16:40.597901 14500 heartbeater.cc:344] Connected to a master server at 127.13.123.126:35001
I20260812 06:16:40.598037 14500 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:40.598287 14500 heartbeater.cc:507] Master 127.13.123.126:35001 requested a full tablet report, sending...
I20260812 06:16:40.599144 14255 ts_manager.cc:194] Registered new tserver with Master: cc555f4a2ec24ed98eee3a0be6757aeb (127.13.123.65:44009)
I20260812 06:16:40.599593 13805 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011569473s
I20260812 06:16:40.600080 14255 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55346
I20260812 06:16:40.608850 14255 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55360:
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:40.619336 14432 tablet_service.cc:1511] Processing CreateTablet for tablet 28ebfdf28a4c45c49bd4ee61fceda82a (DEFAULT_TABLE table=heavy-update-compaction-test [id=91473b005d074f9eb99fdff7fae02c6c]), partition=
I20260812 06:16:40.619671 14432 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 28ebfdf28a4c45c49bd4ee61fceda82a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:40.621978 14523 tablet_bootstrap.cc:492] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Bootstrap starting.
I20260812 06:16:40.622885 14523 tablet_bootstrap.cc:654] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.624002 14523 tablet_bootstrap.cc:492] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: No bootstrap required, opened a new log
I20260812 06:16:40.624158 14523 ts_tablet_manager.cc:1403] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:40.624591 14523 raft_consensus.cc:359] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cc555f4a2ec24ed98eee3a0be6757aeb" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44009 } }
I20260812 06:16:40.624716 14523 raft_consensus.cc:385] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.624758 14523 raft_consensus.cc:740] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cc555f4a2ec24ed98eee3a0be6757aeb, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.624923 14523 consensus_queue.cc:260] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [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: "cc555f4a2ec24ed98eee3a0be6757aeb" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44009 } }
I20260812 06:16:40.625036 14523 raft_consensus.cc:399] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.625082 14523 raft_consensus.cc:493] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.625135 14523 raft_consensus.cc:3060] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.625941 14523 raft_consensus.cc:515] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cc555f4a2ec24ed98eee3a0be6757aeb" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44009 } }
I20260812 06:16:40.626065 14523 leader_election.cc:304] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [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: cc555f4a2ec24ed98eee3a0be6757aeb; no voters: 
I20260812 06:16:40.626333 14523 leader_election.cc:290] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.626543 14528 raft_consensus.cc:2804] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.626662 14523 ts_tablet_manager.cc:1434] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:16:40.626683 14500 heartbeater.cc:499] Master 127.13.123.126:35001 was elected leader, sending a full tablet report...
I20260812 06:16:40.626704 14528 raft_consensus.cc:697] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 1 LEADER]: Becoming Leader. State: Replica: cc555f4a2ec24ed98eee3a0be6757aeb, State: Running, Role: LEADER
I20260812 06:16:40.627130 14528 consensus_queue.cc:237] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [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: "cc555f4a2ec24ed98eee3a0be6757aeb" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44009 } }
I20260812 06:16:40.628605 14255 catalog_manager.cc:5719] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb reported cstate change: term changed from 0 to 1, leader changed from <none> to cc555f4a2ec24ed98eee3a0be6757aeb (127.13.123.65). New cstate: current_term: 1 leader_uuid: "cc555f4a2ec24ed98eee3a0be6757aeb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cc555f4a2ec24ed98eee3a0be6757aeb" member_type: VOTER last_known_addr { host: "127.13.123.65" port: 44009 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:40.694937 13805 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.016s	sys 0.008s
I20260812 06:16:40.838543 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushMRSOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=19.054940
I20260812 06:16:41.008598 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushMRSOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.170s	user 0.102s	sys 0.053s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":930,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41172,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:41.009654 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a): free 20743880 bytes of WAL
I20260812 06:16:41.009918 14384 log_reader.cc:385] T 28ebfdf28a4c45c49bd4ee61fceda82a: removed 2 log segments from log reader
I20260812 06:16:41.009987 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000001 (ops 1-6)
I20260812 06:16:41.010059 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000002 (ops 7-11)
I20260812 06:16:41.014511 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:41.014914 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:41.028229 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.028800 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:41.190120 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.161s	user 0.114s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1092,"lbm_read_time_us":10946,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26739,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":414,"threads_started":5,"update_count":2000}
I20260812 06:16:41.190944 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling UndoDeltaBlockGCOp(28ebfdf28a4c45c49bd4ee61fceda82a): 16411396 bytes on disk
I20260812 06:16:41.191532 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: UndoDeltaBlockGCOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.192031 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=12.110812
I20260812 06:16:41.230453 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.038s	user 0.018s	sys 0.019s Metrics: {"bytes_written":14030497,"delete_count":0,"lbm_write_time_us":16638,"lbm_writes_lt_1ms":345,"reinsert_count":0,"update_count":1710}
I20260812 06:16:41.231122 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.196750
I20260812 06:16:41.241819 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2379604,"delete_count":0,"lbm_write_time_us":3559,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:16:41.242463 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:41.399359 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.157s	user 0.096s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672229,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1299,"lbm_read_time_us":9144,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24765,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21376,"update_count":2000}
I20260812 06:16:41.400136 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=14.095187
I20260812 06:16:41.454545 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.054s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21359,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.455065 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:41.476929 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.022s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4496,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.478041 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:41.662704 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.184s	user 0.104s	sys 0.077s 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":1012,"lbm_read_time_us":13726,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28272,"lbm_writes_lt_1ms":543,"mutex_wait_us":312,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:16:41.663311 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=14.095187
I20260812 06:16:41.711869 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.048s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21348,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.712427 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:41.724581 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.725449 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:41.929407 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.204s	user 0.131s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":703,"lbm_read_time_us":12536,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32197,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:16:41.930099 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=14.095187
I20260812 06:16:41.987126 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.057s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20592,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.988014 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:41.999948 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.000458 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:42.153709 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.153s	user 0.106s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":653,"lbm_read_time_us":9766,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30110,"lbm_writes_lt_1ms":543,"mutex_wait_us":284,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:16:42.154506 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=11.118625
I20260812 06:16:42.236398 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.082s	user 0.028s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":42755,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:42.237119 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=6.157687
I20260812 06:16:42.264412 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.027s	user 0.016s	sys 0.004s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9601,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:42.265038 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushMRSOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:42.321516 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushMRSOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.056s	user 0.033s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":275,"dirs.run_cpu_time_us":307,"dirs.run_wall_time_us":1934,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1849,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:42.322201 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a): free 108082399 bytes of WAL
I20260812 06:16:42.322427 14384 log_reader.cc:385] T 28ebfdf28a4c45c49bd4ee61fceda82a: removed 11 log segments from log reader
I20260812 06:16:42.322470 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000003 (ops 12-16)
I20260812 06:16:42.322500 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000004 (ops 17-20)
I20260812 06:16:42.322567 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000005 (ops 21-25)
I20260812 06:16:42.322615 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000006 (ops 26-30)
I20260812 06:16:42.322657 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000007 (ops 31-34)
I20260812 06:16:42.322714 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000008 (ops 35-39)
I20260812 06:16:42.322753 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000009 (ops 40-44)
I20260812 06:16:42.322793 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000010 (ops 45-48)
I20260812 06:16:42.322834 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000011 (ops 49-53)
I20260812 06:16:42.322873 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000012 (ops 54-58)
I20260812 06:16:42.322912 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000013 (ops 59-63)
I20260812 06:16:42.346065 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.024s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:16:42.346509 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling UndoDeltaBlockGCOp(28ebfdf28a4c45c49bd4ee61fceda82a): 462 bytes on disk
I20260812 06:16:42.346944 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: UndoDeltaBlockGCOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.347461 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=6.157687
I20260812 06:16:42.375340 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.028s	user 0.012s	sys 0.011s Metrics: {"bytes_written":8205080,"delete_count":0,"lbm_write_time_us":9389,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:42.375991 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a): free 8767123 bytes of WAL
I20260812 06:16:42.376256 14384 log_reader.cc:385] T 28ebfdf28a4c45c49bd4ee61fceda82a: removed 1 log segments from log reader
I20260812 06:16:42.376327 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000014 (ops 64-68)
I20260812 06:16:42.378192 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:42.378607 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:42.390769 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.391371 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:42.664112 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.273s	user 0.156s	sys 0.116s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082172,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":62,"lbm_read_time_us":19507,"lbm_reads_lt_1ms":874,"lbm_write_time_us":43942,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":296,"threads_started":5,"update_count":4000}
I20260812 06:16:42.664739 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=18.063937
I20260812 06:16:42.729298 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.064s	user 0.048s	sys 0.015s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28637,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:42.730057 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:42.747819 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.018s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.748306 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:42.967197 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.219s	user 0.141s	sys 0.074s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2828,"lbm_read_time_us":15086,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35817,"lbm_writes_lt_1ms":643,"mutex_wait_us":681,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":3000}
I20260812 06:16:42.967872 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=16.079562
I20260812 06:16:43.045549 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.078s	user 0.039s	sys 0.023s Metrics: {"bytes_written":18050866,"delete_count":0,"lbm_write_time_us":31127,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"reinsert_count":0,"update_count":2200}
I20260812 06:16:43.046115 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=5.165500
I20260812 06:16:43.065124 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.019s	user 0.009s	sys 0.007s Metrics: {"bytes_written":6564117,"delete_count":0,"lbm_write_time_us":7648,"lbm_writes_lt_1ms":163,"reinsert_count":0,"update_count":800}
I20260812 06:16:43.065860 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:43.312217 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.246s	user 0.164s	sys 0.073s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":853,"lbm_read_time_us":17911,"lbm_reads_lt_1ms":672,"lbm_write_time_us":41648,"lbm_writes_lt_1ms":643,"mutex_wait_us":326,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":3000}
I20260812 06:16:43.312937 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=18.063937
I20260812 06:16:43.386344 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.073s	user 0.042s	sys 0.026s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":31538,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:43.387357 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:43.398929 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4189,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.399441 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:43.616382 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.217s	user 0.125s	sys 0.091s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":655,"lbm_read_time_us":14894,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36639,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:43.617018 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=14.095187
I20260812 06:16:43.668957 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.052s	user 0.022s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22310,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.669734 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:43.687438 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.688027 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:43.879165 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.191s	user 0.114s	sys 0.064s 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":253,"lbm_read_time_us":13198,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31013,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25600,"update_count":2500}
I20260812 06:16:43.879835 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=14.095187
I20260812 06:16:43.944972 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.065s	user 0.031s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22373,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.945751 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:43.959106 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.959710 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushMRSOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:43.993224 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushMRSOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.033s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":327,"dirs.run_wall_time_us":1674,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1535,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:43.993956 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a): free 123804196 bytes of WAL
I20260812 06:16:43.994189 14384 log_reader.cc:385] T 28ebfdf28a4c45c49bd4ee61fceda82a: removed 12 log segments from log reader
I20260812 06:16:43.994256 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000015 (ops 69-72)
I20260812 06:16:43.994303 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000016 (ops 73-77)
I20260812 06:16:43.994364 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000017 (ops 78-82)
I20260812 06:16:43.994405 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000018 (ops 83-86)
I20260812 06:16:43.994442 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000019 (ops 87-91)
I20260812 06:16:43.994479 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000020 (ops 92-96)
I20260812 06:16:43.994513 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000021 (ops 97-101)
I20260812 06:16:43.994549 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000022 (ops 102-106)
I20260812 06:16:43.994585 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000023 (ops 107-111)
I20260812 06:16:43.994627 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000024 (ops 112-116)
I20260812 06:16:43.994664 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000025 (ops 117-121)
I20260812 06:16:43.994704 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000026 (ops 122-126)
I20260812 06:16:44.023221 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:44.023708 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:44.041792 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.042490 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling UndoDeltaBlockGCOp(28ebfdf28a4c45c49bd4ee61fceda82a): 472 bytes on disk
I20260812 06:16:44.043011 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: UndoDeltaBlockGCOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.043606 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:44.055802 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.056602 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:44.300290 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.243s	user 0.137s	sys 0.103s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2659,"lbm_read_time_us":17423,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42405,"lbm_writes_lt_1ms":743,"mutex_wait_us":2327,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":38528,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:16:44.301039 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=18.063937
I20260812 06:16:44.371865 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.071s	user 0.040s	sys 0.022s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":30077,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:44.372347 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=3.181125
I20260812 06:16:44.384626 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4772,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:44.385258 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:44.395249 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3594,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.395732 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:44.593926 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.198s	user 0.145s	sys 0.047s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979623,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":255,"lbm_read_time_us":15353,"lbm_reads_lt_1ms":773,"lbm_write_time_us":39878,"lbm_writes_lt_1ms":743,"mutex_wait_us":19,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":121088,"update_count":3500}
I20260812 06:16:44.594825 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=15.087375
I20260812 06:16:44.647195 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.052s	user 0.030s	sys 0.018s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":22030,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:44.647758 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:44.666807 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.019s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.667476 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:44.679247 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.011s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.679939 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:44.873188 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.193s	user 0.164s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1063,"lbm_read_time_us":13240,"lbm_reads_lt_1ms":673,"lbm_write_time_us":42545,"lbm_writes_lt_1ms":643,"mutex_wait_us":277,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":30464,"update_count":3000}
I20260812 06:16:44.873907 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=14.095187
I20260812 06:16:44.927223 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.053s	user 0.040s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23881,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.927887 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:44.940654 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.941316 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:45.113366 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.172s	user 0.117s	sys 0.045s 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":1176,"lbm_read_time_us":11636,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32156,"lbm_writes_lt_1ms":543,"mutex_wait_us":416,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":53120,"update_count":2500}
I20260812 06:16:45.114048 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=14.095187
I20260812 06:16:45.166684 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.052s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23163,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.169862 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:45.338383 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.166s	user 0.130s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":160,"lbm_read_time_us":12129,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28724,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:16:45.339272 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=10.126437
I20260812 06:16:45.375818 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.036s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15153,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.376601 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:45.390808 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.391376 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushMRSOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:45.421567 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushMRSOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.030s	user 0.026s	sys 0.002s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":341,"dirs.run_wall_time_us":1899,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2694,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:45.422272 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a): free 121006684 bytes of WAL
I20260812 06:16:45.422513 14384 log_reader.cc:385] T 28ebfdf28a4c45c49bd4ee61fceda82a: removed 12 log segments from log reader
I20260812 06:16:45.422559 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000027 (ops 127-131)
I20260812 06:16:45.422588 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000028 (ops 132-136)
I20260812 06:16:45.422643 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000029 (ops 137-141)
I20260812 06:16:45.422688 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000030 (ops 142-146)
I20260812 06:16:45.422713 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000031 (ops 147-151)
I20260812 06:16:45.422772 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000032 (ops 152-156)
I20260812 06:16:45.422835 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000033 (ops 157-160)
I20260812 06:16:45.422873 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000034 (ops 161-165)
I20260812 06:16:45.422910 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000035 (ops 166-170)
I20260812 06:16:45.422950 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000036 (ops 171-175)
I20260812 06:16:45.422989 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000037 (ops 176-180)
I20260812 06:16:45.423028 14384 log.cc:1079] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: Deleting log segment in path: /tmp/dist-test-tasknw6ZKH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515394364110-13805-0/minicluster-data/ts-0-root/wals/28ebfdf28a4c45c49bd4ee61fceda82a/wal-000000038 (ops 181-185)
I20260812 06:16:45.450107 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: LogGCOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:45.450717 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling UndoDeltaBlockGCOp(28ebfdf28a4c45c49bd4ee61fceda82a): 462 bytes on disk
I20260812 06:16:45.451162 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: UndoDeltaBlockGCOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.451716 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=4.173312
I20260812 06:16:45.472466 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.021s	user 0.018s	sys 0.000s Metrics: {"bytes_written":5948755,"delete_count":0,"lbm_write_time_us":8415,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:16:45.473040 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.196750
I20260812 06:16:45.484359 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2256529,"delete_count":0,"lbm_write_time_us":3509,"lbm_writes_lt_1ms":58,"reinsert_count":0,"update_count":275}
I20260812 06:16:45.485565 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:45.704571 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.219s	user 0.138s	sys 0.077s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877300,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2363,"lbm_read_time_us":14740,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36636,"lbm_writes_lt_1ms":643,"mutex_wait_us":1868,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13184,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:16:45.705433 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=15.087375
I20260812 06:16:45.766795 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.061s	user 0.024s	sys 0.036s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":21899,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:45.767520 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:45.790475 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.023s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4865,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.790997 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=2.188937
I20260812 06:16:45.802172 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: FlushDeltaMemStoresOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.802722 14503 maintenance_manager.cc:419] P cc555f4a2ec24ed98eee3a0be6757aeb: Scheduling MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a): perf score=1.000000
I20260812 06:16:45.843649 13805 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.149s	user 1.931s	sys 0.148s
I20260812 06:16:45.927717 13805 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.084s	user 0.003s	sys 0.000s
I20260812 06:16:45.928457 13805 tablet_server.cc:179] TabletServer@127.13.123.65:0 shutting down...
I20260812 06:16:45.982151 14384 maintenance_manager.cc:643] P cc555f4a2ec24ed98eee3a0be6757aeb: MajorDeltaCompactionOp(28ebfdf28a4c45c49bd4ee61fceda82a) complete. Timing: real 0.179s	user 0.118s	sys 0.061s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":668,"lbm_read_time_us":13512,"lbm_reads_lt_1ms":669,"lbm_write_time_us":31721,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":3000}
I20260812 06:16:45.982901 13805 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:45.983142 13805 tablet_replica.cc:333] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb: stopping tablet replica
I20260812 06:16:45.983304 13805 raft_consensus.cc:2243] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.983501 13805 raft_consensus.cc:2272] T 28ebfdf28a4c45c49bd4ee61fceda82a P cc555f4a2ec24ed98eee3a0be6757aeb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:46.001441 13805 tablet_server.cc:196] TabletServer@127.13.123.65:0 shutdown complete.
I20260812 06:16:46.035331 13805 master.cc:562] Master@127.13.123.126:35001 shutting down...
I20260812 06:16:46.040103 13805 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:46.040437 13805 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:46.040548 13805 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5e05f9cf6d304b64951a9d73f7de7f98: stopping tablet replica
I20260812 06:16:46.053808 13805 master.cc:584] Master@127.13.123.126:35001 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5708 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11776 ms total)

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