[==========] 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:24.178567 20088 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.158.62:33733
I20260812 06:16:24.179629 20088 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:24.180317 20088 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:24.186709 20098 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:24.186724 20093 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:24.186903 20095 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:24.186908 20088 server_base.cc:1061] running on GCE node
I20260812 06:16:24.187458 20088 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:24.187549 20088 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:24.187613 20088 hybrid_clock.cc:648] HybridClock initialized: now 1786515384187611 us; error 0 us; skew 500 ppm
I20260812 06:16:24.189361 20088 webserver.cc:533] Webserver started at http://127.19.158.62:34467/ using document root <none> and password file <none>
I20260812 06:16:24.189920 20088 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:24.189980 20088 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:24.190176 20088 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:24.191816 20088 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/master-0-root/instance:
uuid: "6d0ecf221a02408e960f737f654aa11a"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-t3q3"
I20260812 06:16:24.195279 20088 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.001s
I20260812 06:16:24.197319 20110 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:24.198304 20088 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:24.198446 20088 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/master-0-root
uuid: "6d0ecf221a02408e960f737f654aa11a"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-t3q3"
I20260812 06:16:24.198552 20088 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-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:24.230216 20088 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:24.230878 20088 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:24.231067 20088 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:24.238929 20088 rpc_server.cc:307] RPC server started. Bound to: 127.19.158.62:33733
I20260812 06:16:24.238946 20194 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.158.62:33733 every 8 connection(s)
I20260812 06:16:24.241261 20195 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:24.246547 20195 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a: Bootstrap starting.
I20260812 06:16:24.248914 20195 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:24.249730 20195 log.cc:826] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:24.251271 20195 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a: No bootstrap required, opened a new log
I20260812 06:16:24.254056 20195 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d0ecf221a02408e960f737f654aa11a" member_type: VOTER }
I20260812 06:16:24.254210 20195 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:24.254257 20195 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6d0ecf221a02408e960f737f654aa11a, State: Initialized, Role: FOLLOWER
I20260812 06:16:24.254801 20195 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [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: "6d0ecf221a02408e960f737f654aa11a" member_type: VOTER }
I20260812 06:16:24.254930 20195 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:24.254974 20195 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:24.255053 20195 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:24.255797 20195 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d0ecf221a02408e960f737f654aa11a" member_type: VOTER }
I20260812 06:16:24.256177 20195 leader_election.cc:304] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [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: 6d0ecf221a02408e960f737f654aa11a; no voters: 
I20260812 06:16:24.256424 20195 leader_election.cc:290] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:24.256564 20200 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:24.256824 20200 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 1 LEADER]: Becoming Leader. State: Replica: 6d0ecf221a02408e960f737f654aa11a, State: Running, Role: LEADER
I20260812 06:16:24.257243 20200 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [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: "6d0ecf221a02408e960f737f654aa11a" member_type: VOTER }
I20260812 06:16:24.257452 20195 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:24.259267 20203 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6d0ecf221a02408e960f737f654aa11a. Latest consensus state: current_term: 1 leader_uuid: "6d0ecf221a02408e960f737f654aa11a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d0ecf221a02408e960f737f654aa11a" member_type: VOTER } }
I20260812 06:16:24.259268 20202 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6d0ecf221a02408e960f737f654aa11a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6d0ecf221a02408e960f737f654aa11a" member_type: VOTER } }
I20260812 06:16:24.259433 20202 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:24.259433 20203 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:24.259672 20088 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:24.259929 20228 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:24.262121 20228 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:24.266698 20228 catalog_manager.cc:1383] Generated new cluster ID: 6b4851d4baf948578ab5fa91f0697534
I20260812 06:16:24.266764 20228 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:24.283244 20228 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:24.284163 20228 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:24.294533 20228 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a: Generated new TSK 0
I20260812 06:16:24.295150 20228 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:24.324751 20088 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:24.328218 20234 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:24.328226 20088 server_base.cc:1061] running on GCE node
W20260812 06:16:24.328348 20239 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:24.328382 20236 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:24.328733 20088 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:24.328789 20088 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:24.328812 20088 hybrid_clock.cc:648] HybridClock initialized: now 1786515384328812 us; error 0 us; skew 500 ppm
I20260812 06:16:24.329784 20088 webserver.cc:533] Webserver started at http://127.19.158.1:35257/ using document root <none> and password file <none>
I20260812 06:16:24.329960 20088 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:24.330017 20088 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:24.330101 20088 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:24.330562 20088 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/instance:
uuid: "f3003d6482d6457bb09d2839fc017fd6"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-t3q3"
I20260812 06:16:24.332475 20088 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:24.333616 20247 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:24.333902 20088 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:24.333999 20088 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root
uuid: "f3003d6482d6457bb09d2839fc017fd6"
format_stamp: "Formatted at 2026-08-12 06:16:24 on dist-test-slave-t3q3"
I20260812 06:16:24.334091 20088 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-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:24.355712 20088 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:24.356261 20088 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:24.356778 20088 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:24.357615 20088 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:24.357692 20088 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:24.357770 20088 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:24.357825 20088 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:24.364231 20088 rpc_server.cc:307] RPC server started. Bound to: 127.19.158.1:45751
I20260812 06:16:24.364346 20338 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.158.1:45751 every 8 connection(s)
I20260812 06:16:24.378736 20339 heartbeater.cc:344] Connected to a master server at 127.19.158.62:33733
I20260812 06:16:24.379004 20339 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:24.379520 20339 heartbeater.cc:507] Master 127.19.158.62:33733 requested a full tablet report, sending...
I20260812 06:16:24.381057 20139 ts_manager.cc:194] Registered new tserver with Master: f3003d6482d6457bb09d2839fc017fd6 (127.19.158.1:45751)
I20260812 06:16:24.381636 20088 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016722696s
I20260812 06:16:24.382506 20139 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49856
I20260812 06:16:24.392115 20139 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49868:
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:24.412930 20288 tablet_service.cc:1511] Processing CreateTablet for tablet d57c4c2823964e2d841bad7b2b6f35ca (DEFAULT_TABLE table=heavy-update-compaction-test [id=8c0ee517c72049d0bf386b5c81ab5bfe]), partition=
I20260812 06:16:24.413421 20288 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d57c4c2823964e2d841bad7b2b6f35ca. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:24.416505 20355 tablet_bootstrap.cc:492] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Bootstrap starting.
I20260812 06:16:24.422472 20355 tablet_bootstrap.cc:654] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:24.425659 20355 tablet_bootstrap.cc:492] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: No bootstrap required, opened a new log
I20260812 06:16:24.425802 20355 ts_tablet_manager.cc:1403] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Time spent bootstrapping tablet: real 0.009s	user 0.005s	sys 0.000s
I20260812 06:16:24.426950 20355 raft_consensus.cc:359] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3003d6482d6457bb09d2839fc017fd6" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 45751 } }
I20260812 06:16:24.427103 20355 raft_consensus.cc:385] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:24.427146 20355 raft_consensus.cc:740] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f3003d6482d6457bb09d2839fc017fd6, State: Initialized, Role: FOLLOWER
I20260812 06:16:24.427299 20355 consensus_queue.cc:260] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [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: "f3003d6482d6457bb09d2839fc017fd6" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 45751 } }
I20260812 06:16:24.427414 20355 raft_consensus.cc:399] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:24.427460 20355 raft_consensus.cc:493] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:24.427515 20355 raft_consensus.cc:3060] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:24.429011 20355 raft_consensus.cc:515] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3003d6482d6457bb09d2839fc017fd6" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 45751 } }
I20260812 06:16:24.429174 20355 leader_election.cc:304] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [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: f3003d6482d6457bb09d2839fc017fd6; no voters: 
I20260812 06:16:24.429425 20355 leader_election.cc:290] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:24.429661 20358 raft_consensus.cc:2804] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:24.429785 20355 ts_tablet_manager.cc:1434] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Time spent starting tablet: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:16:24.429913 20358 raft_consensus.cc:697] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 1 LEADER]: Becoming Leader. State: Replica: f3003d6482d6457bb09d2839fc017fd6, State: Running, Role: LEADER
I20260812 06:16:24.430076 20358 consensus_queue.cc:237] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [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: "f3003d6482d6457bb09d2839fc017fd6" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 45751 } }
I20260812 06:16:24.430320 20339 heartbeater.cc:499] Master 127.19.158.62:33733 was elected leader, sending a full tablet report...
I20260812 06:16:24.433221 20139 catalog_manager.cc:5719] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 reported cstate change: term changed from 0 to 1, leader changed from <none> to f3003d6482d6457bb09d2839fc017fd6 (127.19.158.1). New cstate: current_term: 1 leader_uuid: "f3003d6482d6457bb09d2839fc017fd6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3003d6482d6457bb09d2839fc017fd6" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 45751 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:24.531404 20088 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.092s	user 0.018s	sys 0.012s
I20260812 06:16:24.615387 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushMRSOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.125253
I20260812 06:16:24.756879 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushMRSOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.141s	user 0.109s	sys 0.024s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":220,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":936,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":30448,"lbm_writes_lt_1ms":467,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"spinlock_wait_cycles":223616,"thread_start_us":141,"threads_started":1,"update_count":1050}
I20260812 06:16:24.758104 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca): free 8725963 bytes of WAL
I20260812 06:16:24.758423 20253 log_reader.cc:385] T d57c4c2823964e2d841bad7b2b6f35ca: removed 1 log segments from log reader
I20260812 06:16:24.758513 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000001 (ops 1-6)
I20260812 06:16:24.760715 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:24.761042 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling UndoDeltaBlockGCOp(d57c4c2823964e2d841bad7b2b6f35ca): 8206537 bytes on disk
I20260812 06:16:24.761590 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: UndoDeltaBlockGCOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:24.761958 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:24.774039 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4211,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:24.774622 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:24.890461 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.116s	user 0.076s	sys 0.039s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487926,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":997,"lbm_read_time_us":6391,"lbm_reads_lt_1ms":360,"lbm_write_time_us":21994,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":332,"threads_started":5,"update_count":1500}
I20260812 06:16:24.891058 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=7.149875
I20260812 06:16:24.917670 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.026s	user 0.014s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9390,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:24.918463 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:24.927968 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3579,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:24.928458 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:25.063373 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.135s	user 0.087s	sys 0.036s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487926,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":9161,"lbm_reads_lt_1ms":372,"lbm_write_time_us":20862,"lbm_writes_lt_1ms":343,"mutex_wait_us":51,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":73088,"update_count":1500}
I20260812 06:16:25.063885 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:25.114012 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.050s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17970,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.114513 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:25.129628 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5604,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.130172 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:25.263370 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.133s	user 0.102s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1140,"lbm_read_time_us":9134,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26541,"lbm_writes_lt_1ms":443,"mutex_wait_us":348,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:16:25.264029 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:25.309849 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.046s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16079,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.310310 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:25.321225 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3992,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.321887 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:25.450419 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.128s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1284,"lbm_read_time_us":7837,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27524,"lbm_writes_lt_1ms":443,"mutex_wait_us":335,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:25.450978 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:25.503115 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.052s	user 0.016s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22231,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.503633 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:25.514166 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.514621 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:25.661181 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.146s	user 0.101s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":10354,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23749,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:16:25.661810 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:25.710387 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.048s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15068,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.710932 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:25.722069 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.722779 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:25.844884 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.122s	user 0.086s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":619,"lbm_read_time_us":7965,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25672,"lbm_writes_lt_1ms":443,"mutex_wait_us":308,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:16:25.845649 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:25.884980 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.039s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15496,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.885489 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:25.901144 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.901823 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:26.034418 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.132s	user 0.103s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":737,"lbm_read_time_us":8861,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27813,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:16:26.035012 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:26.090214 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.055s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16071,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":388352,"update_count":1500}
I20260812 06:16:26.090885 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:26.102105 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.102710 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushMRSOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:26.145797 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushMRSOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.043s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1233,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1598,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:26.146657 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca): free 123804187 bytes of WAL
I20260812 06:16:26.146891 20253 log_reader.cc:385] T d57c4c2823964e2d841bad7b2b6f35ca: removed 12 log segments from log reader
I20260812 06:16:26.146938 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000002 (ops 7-10)
I20260812 06:16:26.146967 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000003 (ops 11-15)
I20260812 06:16:26.147037 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000004 (ops 16-20)
I20260812 06:16:26.147068 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000005 (ops 21-25)
I20260812 06:16:26.147110 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000006 (ops 26-30)
I20260812 06:16:26.147166 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000007 (ops 31-35)
I20260812 06:16:26.147207 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000008 (ops 36-40)
I20260812 06:16:26.147234 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000009 (ops 41-45)
I20260812 06:16:26.147277 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000010 (ops 46-50)
I20260812 06:16:26.147320 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000011 (ops 51-55)
I20260812 06:16:26.147360 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000012 (ops 56-60)
I20260812 06:16:26.147400 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000013 (ops 61-64)
I20260812 06:16:26.176239 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:26.176689 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=3.181125
I20260812 06:16:26.194859 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.018s	user 0.011s	sys 0.006s Metrics: {"bytes_written":5005191,"delete_count":0,"lbm_write_time_us":7536,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:16:26.195291 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling UndoDeltaBlockGCOp(d57c4c2823964e2d841bad7b2b6f35ca): 472 bytes on disk
I20260812 06:16:26.195686 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: UndoDeltaBlockGCOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:16:26.196204 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:26.204980 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.009s	user 0.002s	sys 0.006s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":3187,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:16:26.205547 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:26.401247 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.195s	user 0.126s	sys 0.069s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795386,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":432,"lbm_read_time_us":12973,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34475,"lbm_writes_lt_1ms":643,"mutex_wait_us":99,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:16:26.401955 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=14.095187
I20260812 06:16:26.464579 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.062s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22421,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.465103 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:26.478938 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.479604 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:26.657096 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.177s	user 0.109s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":663,"lbm_read_time_us":12613,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29595,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:16:26.657754 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=14.095187
I20260812 06:16:26.716555 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.059s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21947,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.717088 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:26.727566 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.727975 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:26.897327 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.169s	user 0.121s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":261,"lbm_read_time_us":14380,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28945,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:26.898088 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:26.929837 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.032s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13688,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:26.930361 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:26.956629 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.026s	user 0.006s	sys 0.019s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.957247 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:27.119637 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.162s	user 0.089s	sys 0.065s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":167,"lbm_read_time_us":10942,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25334,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:16:27.120258 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=14.095187
I20260812 06:16:27.169466 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.049s	user 0.036s	sys 0.005s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19421,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.169966 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:27.181563 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.182250 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:27.330055 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.148s	user 0.110s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":10232,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29343,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:27.330753 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=14.095187
I20260812 06:16:27.386279 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.055s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23552,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.386829 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:27.399224 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.399789 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:27.553200 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.153s	user 0.103s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":309,"lbm_read_time_us":9616,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30895,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:16:27.553908 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=14.095187
I20260812 06:16:27.607247 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.053s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25984,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.607791 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:27.618993 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3992,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.619508 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushMRSOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:27.649554 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushMRSOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1202,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1510,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:27.650314 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca): free 133024374 bytes of WAL
I20260812 06:16:27.650557 20253 log_reader.cc:385] T d57c4c2823964e2d841bad7b2b6f35ca: removed 13 log segments from log reader
I20260812 06:16:27.650605 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000014 (ops 65-69)
I20260812 06:16:27.650635 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000015 (ops 70-74)
I20260812 06:16:27.650700 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000016 (ops 75-79)
I20260812 06:16:27.650743 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000017 (ops 80-84)
I20260812 06:16:27.650789 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000018 (ops 85-89)
I20260812 06:16:27.650826 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000019 (ops 90-94)
I20260812 06:16:27.650889 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000020 (ops 95-99)
I20260812 06:16:27.650930 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000021 (ops 100-104)
I20260812 06:16:27.650969 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000022 (ops 105-108)
I20260812 06:16:27.651010 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000023 (ops 109-113)
I20260812 06:16:27.651048 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000024 (ops 114-118)
I20260812 06:16:27.651088 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000025 (ops 119-123)
I20260812 06:16:27.651131 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000026 (ops 124-128)
I20260812 06:16:27.681133 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:27.681555 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling UndoDeltaBlockGCOp(d57c4c2823964e2d841bad7b2b6f35ca): 482 bytes on disk
I20260812 06:16:27.682053 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: UndoDeltaBlockGCOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:16:27.682576 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=6.157687
I20260812 06:16:27.708784 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.026s	user 0.022s	sys 0.001s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9854,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:27.709411 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:27.893164 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.184s	user 0.140s	sys 0.036s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32897702,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":422,"lbm_read_time_us":12464,"lbm_reads_lt_1ms":765,"lbm_write_time_us":36449,"lbm_writes_lt_1ms":743,"mutex_wait_us":65,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":117,"threads_started":1,"update_count":3500}
I20260812 06:16:27.894011 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=18.063937
I20260812 06:16:27.954550 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.060s	user 0.034s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27000,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:27.955297 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:27.974197 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.019s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6413,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.974660 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:28.136485 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.162s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28795172,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1162,"lbm_read_time_us":11571,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33255,"lbm_writes_lt_1ms":643,"mutex_wait_us":471,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":3000}
I20260812 06:16:28.137185 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=14.095187
I20260812 06:16:28.198498 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.061s	user 0.034s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":31580,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.199105 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:28.221487 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.022s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.221964 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:28.233024 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.233819 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:28.404042 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.170s	user 0.125s	sys 0.042s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795292,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":934,"lbm_read_time_us":12246,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36423,"lbm_writes_lt_1ms":643,"mutex_wait_us":446,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":3000}
I20260812 06:16:28.404754 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=14.095187
I20260812 06:16:28.461763 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.057s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24706,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.462296 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:28.473781 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.474285 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:28.635807 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.161s	user 0.117s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692756,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":10350,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30278,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:28.636693 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=14.095187
I20260812 06:16:28.680809 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.044s	user 0.034s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18606,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.681505 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:28.845137 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.163s	user 0.131s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590227,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1058,"lbm_read_time_us":11487,"lbm_reads_lt_1ms":467,"lbm_write_time_us":32025,"lbm_writes_lt_1ms":443,"mutex_wait_us":286,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2000}
I20260812 06:16:28.845829 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:28.879329 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.033s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15036,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:28.879871 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:28.893559 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.896425 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:29.017889 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.121s	user 0.092s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":397,"lbm_read_time_us":9847,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24335,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26752,"update_count":2000}
I20260812 06:16:29.018718 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:29.066672 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.048s	user 0.027s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20022,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.067267 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:29.090819 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.023s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.091436 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushMRSOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:29.141408 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushMRSOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.050s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1364,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1820,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:29.142158 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca): free 121006640 bytes of WAL
I20260812 06:16:29.142441 20253 log_reader.cc:385] T d57c4c2823964e2d841bad7b2b6f35ca: removed 12 log segments from log reader
I20260812 06:16:29.142508 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000027 (ops 129-133)
I20260812 06:16:29.142549 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000028 (ops 134-138)
I20260812 06:16:29.142580 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000029 (ops 139-143)
I20260812 06:16:29.142606 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000030 (ops 144-148)
I20260812 06:16:29.142638 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000031 (ops 149-152)
I20260812 06:16:29.142674 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000032 (ops 153-157)
I20260812 06:16:29.142706 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000033 (ops 158-162)
I20260812 06:16:29.142732 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000034 (ops 163-167)
I20260812 06:16:29.142761 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000035 (ops 168-172)
I20260812 06:16:29.142791 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000036 (ops 173-177)
I20260812 06:16:29.142825 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000037 (ops 178-182)
I20260812 06:16:29.142858 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000038 (ops 183-187)
I20260812 06:16:29.172878 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:29.173352 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=7.149875
I20260812 06:16:29.202661 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.029s	user 0.017s	sys 0.010s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12496,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:29.203146 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca): free 12018004 bytes of WAL
I20260812 06:16:29.203364 20253 log_reader.cc:385] T d57c4c2823964e2d841bad7b2b6f35ca: removed 1 log segments from log reader
I20260812 06:16:29.203411 20253 log.cc:1079] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/d57c4c2823964e2d841bad7b2b6f35ca/wal-000000039 (ops 188-192)
I20260812 06:16:29.205876 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: LogGCOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:29.206211 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=2.188937
I20260812 06:16:29.217701 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4434,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:29.218189 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling UndoDeltaBlockGCOp(d57c4c2823964e2d841bad7b2b6f35ca): 492 bytes on disk
I20260812 06:16:29.218626 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: UndoDeltaBlockGCOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:16:29.219185 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=1.000000
I20260812 06:16:29.342031 20088 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.811s	user 1.792s	sys 0.114s
I20260812 06:16:29.409791 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: MajorDeltaCompactionOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.190s	user 0.128s	sys 0.059s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897812,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14980,"lbm_reads_lt_1ms":770,"lbm_write_time_us":36027,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":3500}
I20260812 06:16:29.410281 20340 maintenance_manager.cc:419] P f3003d6482d6457bb09d2839fc017fd6: Scheduling FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca): perf score=10.126437
I20260812 06:16:29.428467 20088 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.086s	user 0.003s	sys 0.000s
I20260812 06:16:29.429136 20088 tablet_server.cc:179] TabletServer@127.19.158.1:0 shutting down...
I20260812 06:16:29.461024 20253 maintenance_manager.cc:643] P f3003d6482d6457bb09d2839fc017fd6: FlushDeltaMemStoresOp(d57c4c2823964e2d841bad7b2b6f35ca) complete. Timing: real 0.051s	user 0.012s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":33214,"lbm_writes_1-10_ms":1,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.461757 20088 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:29.462173 20088 tablet_replica.cc:333] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6: stopping tablet replica
I20260812 06:16:29.462409 20088 raft_consensus.cc:2243] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:29.462651 20088 raft_consensus.cc:2272] T d57c4c2823964e2d841bad7b2b6f35ca P f3003d6482d6457bb09d2839fc017fd6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:29.477996 20088 tablet_server.cc:196] TabletServer@127.19.158.1:0 shutdown complete.
I20260812 06:16:29.482796 20088 master.cc:562] Master@127.19.158.62:33733 shutting down...
I20260812 06:16:29.487129 20088 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:29.487317 20088 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:29.487414 20088 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6d0ecf221a02408e960f737f654aa11a: stopping tablet replica
I20260812 06:16:29.499816 20088 master.cc:584] Master@127.19.158.62:33733 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5412 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:29.602653 20088 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.158.62:36975
I20260812 06:16:29.603086 20088 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:29.605329 20392 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:29.605429 20395 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:29.605454 20088 server_base.cc:1061] running on GCE node
W20260812 06:16:29.605463 20390 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:29.605758 20088 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:29.605813 20088 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:29.605829 20088 hybrid_clock.cc:648] HybridClock initialized: now 1786515389605830 us; error 0 us; skew 500 ppm
I20260812 06:16:29.606788 20088 webserver.cc:533] Webserver started at http://127.19.158.62:45935/ using document root <none> and password file <none>
I20260812 06:16:29.606966 20088 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:29.607015 20088 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:29.607090 20088 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:29.607527 20088 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/master-0-root/instance:
uuid: "3956fa3a3cec43b98a06989d9d1651cc"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-t3q3"
I20260812 06:16:29.609563 20088 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:29.610704 20401 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:29.610929 20088 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:29.610996 20088 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/master-0-root
uuid: "3956fa3a3cec43b98a06989d9d1651cc"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-t3q3"
I20260812 06:16:29.611054 20088 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-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:29.617115 20088 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:29.617439 20088 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:29.621927 20088 rpc_server.cc:307] RPC server started. Bound to: 127.19.158.62:36975
I20260812 06:16:29.623019 20480 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.158.62:36975 every 8 connection(s)
I20260812 06:16:29.628836 20481 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:29.631235 20481 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc: Bootstrap starting.
I20260812 06:16:29.631981 20481 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:29.633100 20481 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc: No bootstrap required, opened a new log
I20260812 06:16:29.633549 20481 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3956fa3a3cec43b98a06989d9d1651cc" member_type: VOTER }
I20260812 06:16:29.633637 20481 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:29.633701 20481 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3956fa3a3cec43b98a06989d9d1651cc, State: Initialized, Role: FOLLOWER
I20260812 06:16:29.633891 20481 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [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: "3956fa3a3cec43b98a06989d9d1651cc" member_type: VOTER }
I20260812 06:16:29.633965 20481 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:29.634023 20481 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:29.634083 20481 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:29.634763 20481 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3956fa3a3cec43b98a06989d9d1651cc" member_type: VOTER }
I20260812 06:16:29.634917 20481 leader_election.cc:304] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [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: 3956fa3a3cec43b98a06989d9d1651cc; no voters: 
I20260812 06:16:29.635143 20481 leader_election.cc:290] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:29.635289 20486 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:29.635522 20486 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 1 LEADER]: Becoming Leader. State: Replica: 3956fa3a3cec43b98a06989d9d1651cc, State: Running, Role: LEADER
I20260812 06:16:29.635608 20481 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:29.635696 20486 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [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: "3956fa3a3cec43b98a06989d9d1651cc" member_type: VOTER }
I20260812 06:16:29.636206 20488 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3956fa3a3cec43b98a06989d9d1651cc. Latest consensus state: current_term: 1 leader_uuid: "3956fa3a3cec43b98a06989d9d1651cc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3956fa3a3cec43b98a06989d9d1651cc" member_type: VOTER } }
I20260812 06:16:29.636189 20487 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3956fa3a3cec43b98a06989d9d1651cc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3956fa3a3cec43b98a06989d9d1651cc" member_type: VOTER } }
I20260812 06:16:29.636329 20488 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:29.636396 20487 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:29.636878 20498 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:29.637530 20498 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:29.637705 20088 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:29.639246 20498 catalog_manager.cc:1383] Generated new cluster ID: 0fb2119fdc2045bf95bdf848fb97bb79
I20260812 06:16:29.639317 20498 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:29.668118 20498 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:29.668704 20498 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:29.674700 20498 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc: Generated new TSK 0
I20260812 06:16:29.674906 20498 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:29.702368 20088 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:29.704496 20515 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:29.704537 20520 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:29.704556 20518 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:29.704842 20088 server_base.cc:1061] running on GCE node
I20260812 06:16:29.705058 20088 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:29.705101 20088 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:29.705143 20088 hybrid_clock.cc:648] HybridClock initialized: now 1786515389705142 us; error 0 us; skew 500 ppm
I20260812 06:16:29.706059 20088 webserver.cc:533] Webserver started at http://127.19.158.1:44497/ using document root <none> and password file <none>
I20260812 06:16:29.706243 20088 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:29.706328 20088 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:29.706416 20088 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:29.706840 20088 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/instance:
uuid: "7916d0e437074eea80357edba049a5b4"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-t3q3"
I20260812 06:16:29.708412 20088 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:29.709352 20528 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:29.709618 20088 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:29.709705 20088 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root
uuid: "7916d0e437074eea80357edba049a5b4"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-t3q3"
I20260812 06:16:29.709792 20088 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-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:29.732034 20088 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:29.732549 20088 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:29.732884 20088 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:29.733398 20088 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:29.733465 20088 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.733530 20088 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:29.733567 20088 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.738202 20088 rpc_server.cc:307] RPC server started. Bound to: 127.19.158.1:42479
I20260812 06:16:29.738248 20630 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.158.1:42479 every 8 connection(s)
I20260812 06:16:29.746183 20632 heartbeater.cc:344] Connected to a master server at 127.19.158.62:36975
I20260812 06:16:29.746331 20632 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:29.746604 20632 heartbeater.cc:507] Master 127.19.158.62:36975 requested a full tablet report, sending...
I20260812 06:16:29.747284 20427 ts_manager.cc:194] Registered new tserver with Master: 7916d0e437074eea80357edba049a5b4 (127.19.158.1:42479)
I20260812 06:16:29.747552 20088 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00888268s
I20260812 06:16:29.748297 20427 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44142
I20260812 06:16:29.757404 20427 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44156:
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:29.767753 20580 tablet_service.cc:1511] Processing CreateTablet for tablet 54be331f6c784345a1afc034e943f98d (DEFAULT_TABLE table=heavy-update-compaction-test [id=878ef097ef7b4164b3b9cbcd6be9063e]), partition=
I20260812 06:16:29.768123 20580 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 54be331f6c784345a1afc034e943f98d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:29.770320 20653 tablet_bootstrap.cc:492] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Bootstrap starting.
I20260812 06:16:29.771256 20653 tablet_bootstrap.cc:654] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:29.772481 20653 tablet_bootstrap.cc:492] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: No bootstrap required, opened a new log
I20260812 06:16:29.772593 20653 ts_tablet_manager.cc:1403] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:29.773150 20653 raft_consensus.cc:359] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7916d0e437074eea80357edba049a5b4" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 42479 } }
I20260812 06:16:29.773285 20653 raft_consensus.cc:385] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:29.773350 20653 raft_consensus.cc:740] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7916d0e437074eea80357edba049a5b4, State: Initialized, Role: FOLLOWER
I20260812 06:16:29.773515 20653 consensus_queue.cc:260] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [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: "7916d0e437074eea80357edba049a5b4" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 42479 } }
I20260812 06:16:29.773620 20653 raft_consensus.cc:399] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:29.773675 20653 raft_consensus.cc:493] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:29.773733 20653 raft_consensus.cc:3060] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:29.774477 20653 raft_consensus.cc:515] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7916d0e437074eea80357edba049a5b4" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 42479 } }
I20260812 06:16:29.774633 20653 leader_election.cc:304] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [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: 7916d0e437074eea80357edba049a5b4; no voters: 
I20260812 06:16:29.774868 20653 leader_election.cc:290] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:29.775014 20655 raft_consensus.cc:2804] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:29.775193 20655 raft_consensus.cc:697] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 1 LEADER]: Becoming Leader. State: Replica: 7916d0e437074eea80357edba049a5b4, State: Running, Role: LEADER
I20260812 06:16:29.775219 20653 ts_tablet_manager.cc:1434] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:29.775230 20632 heartbeater.cc:499] Master 127.19.158.62:36975 was elected leader, sending a full tablet report...
I20260812 06:16:29.775348 20655 consensus_queue.cc:237] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [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: "7916d0e437074eea80357edba049a5b4" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 42479 } }
I20260812 06:16:29.776724 20427 catalog_manager.cc:5719] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 reported cstate change: term changed from 0 to 1, leader changed from <none> to 7916d0e437074eea80357edba049a5b4 (127.19.158.1). New cstate: current_term: 1 leader_uuid: "7916d0e437074eea80357edba049a5b4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7916d0e437074eea80357edba049a5b4" member_type: VOTER last_known_addr { host: "127.19.158.1" port: 42479 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:29.837316 20088 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.023s	sys 0.000s
I20260812 06:16:29.989135 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushMRSOp(54be331f6c784345a1afc034e943f98d): perf score=19.054940
I20260812 06:16:30.143291 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushMRSOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.154s	user 0.111s	sys 0.040s Metrics: {"bytes_written":12717735,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":781,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39148,"lbm_writes_lt_1ms":777,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1792,"update_count":1550}
I20260812 06:16:30.144033 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling LogGCOp(54be331f6c784345a1afc034e943f98d): free 20743880 bytes of WAL
I20260812 06:16:30.144335 20534 log_reader.cc:385] T 54be331f6c784345a1afc034e943f98d: removed 2 log segments from log reader
I20260812 06:16:30.144380 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000001 (ops 1-6)
I20260812 06:16:30.144409 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000002 (ops 7-11)
I20260812 06:16:30.150184 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: LogGCOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:30.150593 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:30.166349 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.016s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692410,"delete_count":0,"lbm_write_time_us":3675,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:30.166771 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:30.176788 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3697,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:30.177253 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:30.349310 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.172s	user 0.110s	sys 0.057s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405545,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":268,"lbm_read_time_us":12473,"lbm_reads_lt_1ms":563,"lbm_write_time_us":28520,"lbm_writes_lt_1ms":533,"mutex_wait_us":56,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":321,"threads_started":5,"update_count":2450}
I20260812 06:16:30.349928 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=14.095187
I20260812 06:16:30.412746 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.063s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26344,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.413264 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling UndoDeltaBlockGCOp(54be331f6c784345a1afc034e943f98d): 16821648 bytes on disk
I20260812 06:16:30.413658 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: UndoDeltaBlockGCOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:16:30.414069 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:30.575688 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.161s	user 0.109s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":231,"lbm_read_time_us":12517,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24381,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":2000}
I20260812 06:16:30.576567 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=14.095187
I20260812 06:16:30.629606 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.053s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24181,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.630153 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:30.652705 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.022s	user 0.007s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.653373 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:30.843505 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.190s	user 0.133s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":13112,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29796,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:16:30.844020 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=14.095187
I20260812 06:16:30.896577 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.052s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21456,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.897128 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:30.911489 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.911974 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:31.067344 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.155s	user 0.119s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":376,"lbm_read_time_us":10703,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29510,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:16:31.067973 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=11.118625
I20260812 06:16:31.105485 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.037s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15934,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:31.106195 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:31.118857 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4893,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.119289 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:31.254581 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.135s	user 0.103s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":153,"lbm_read_time_us":8752,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27506,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:16:31.255306 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=10.126437
I20260812 06:16:31.299016 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.043s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15262,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.299535 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:31.310527 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4022,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.311287 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:31.436201 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.125s	user 0.101s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":475,"lbm_read_time_us":8785,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23316,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":148480,"update_count":2000}
I20260812 06:16:31.437166 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=10.126437
I20260812 06:16:31.486538 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.049s	user 0.035s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18318,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.487100 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:31.498275 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.498797 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushMRSOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:31.542681 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushMRSOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.044s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":171,"dirs.run_wall_time_us":1238,"drs_written":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1621,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:31.543322 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling LogGCOp(54be331f6c784345a1afc034e943f98d): free 124710308 bytes of WAL
I20260812 06:16:31.543552 20534 log_reader.cc:385] T 54be331f6c784345a1afc034e943f98d: removed 12 log segments from log reader
I20260812 06:16:31.543596 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000003 (ops 12-16)
I20260812 06:16:31.543658 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000004 (ops 17-21)
I20260812 06:16:31.543705 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000005 (ops 22-26)
I20260812 06:16:31.543769 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000006 (ops 27-31)
I20260812 06:16:31.543808 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000007 (ops 32-36)
I20260812 06:16:31.543872 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000008 (ops 37-41)
I20260812 06:16:31.543912 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000009 (ops 42-46)
I20260812 06:16:31.543951 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000010 (ops 47-51)
I20260812 06:16:31.543991 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000011 (ops 52-56)
I20260812 06:16:31.544030 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000012 (ops 57-61)
I20260812 06:16:31.544092 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000013 (ops 62-66)
I20260812 06:16:31.544135 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000014 (ops 67-71)
I20260812 06:16:31.572100 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: LogGCOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.029s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:16:31.572697 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=3.181125
I20260812 06:16:31.585870 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4307783,"delete_count":0,"lbm_write_time_us":4373,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:16:31.586383 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling UndoDeltaBlockGCOp(54be331f6c784345a1afc034e943f98d): 472 bytes on disk
I20260812 06:16:31.586864 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: UndoDeltaBlockGCOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:16:31.587340 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:31.601649 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":5403,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:16:31.602209 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:31.807972 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.206s	user 0.153s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918335,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":254,"lbm_read_time_us":16290,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32447,"lbm_writes_lt_1ms":643,"mutex_wait_us":72,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:16:31.808724 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=15.087375
I20260812 06:16:31.862301 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.050s	user 0.040s	sys 0.007s Metrics: {"bytes_written":16820124,"delete_count":0,"lbm_write_time_us":21755,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:31.862998 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:31.874961 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3910,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.875515 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:32.058386 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.183s	user 0.127s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815652,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":139,"lbm_read_time_us":13795,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31596,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:16:32.058998 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=15.087375
I20260812 06:16:32.113850 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.055s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":20267,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:32.114413 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:32.129500 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.015s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:16:32.129920 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:32.140019 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":3921,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:16:32.140487 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:32.352177 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.212s	user 0.153s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":177,"lbm_read_time_us":14119,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34310,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":3000}
I20260812 06:16:32.352903 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=16.079562
I20260812 06:16:32.407514 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.054s	user 0.037s	sys 0.012s Metrics: {"bytes_written":17640628,"delete_count":0,"lbm_write_time_us":23420,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2150}
I20260812 06:16:32.408039 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:32.427860 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.019s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":4930,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:16:32.428380 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:32.437985 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3521,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:32.438567 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:32.640247 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.201s	user 0.121s	sys 0.079s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918187,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":408,"lbm_read_time_us":13581,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32520,"lbm_writes_lt_1ms":643,"mutex_wait_us":70,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":3000}
I20260812 06:16:32.640986 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=16.079562
I20260812 06:16:32.689064 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.048s	user 0.029s	sys 0.017s Metrics: {"bytes_written":17722676,"delete_count":0,"lbm_write_time_us":21095,"lbm_writes_lt_1ms":435,"reinsert_count":0,"update_count":2160}
I20260812 06:16:32.689815 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=1.196750
I20260812 06:16:32.708295 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.018s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3554,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:16:32.708757 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:32.719743 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4151,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.720449 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:32.931139 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.210s	user 0.138s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918184,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":168,"lbm_read_time_us":15372,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35082,"lbm_writes_lt_1ms":643,"mutex_wait_us":71,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3000}
I20260812 06:16:32.932050 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=15.087375
I20260812 06:16:32.986297 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.054s	user 0.020s	sys 0.025s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":20527,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:32.986865 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:32.998160 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.998672 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:33.012471 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.014s	user 0.002s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5240,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:33.013015 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushMRSOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:33.050782 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushMRSOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.038s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":170,"dirs.run_wall_time_us":1213,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2200,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:33.051481 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling LogGCOp(54be331f6c784345a1afc034e943f98d): free 132571369 bytes of WAL
I20260812 06:16:33.051728 20534 log_reader.cc:385] T 54be331f6c784345a1afc034e943f98d: removed 13 log segments from log reader
I20260812 06:16:33.051774 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000015 (ops 72-76)
I20260812 06:16:33.051805 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000016 (ops 77-81)
I20260812 06:16:33.051877 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000017 (ops 82-86)
I20260812 06:16:33.051920 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000018 (ops 87-90)
I20260812 06:16:33.051967 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000019 (ops 91-95)
I20260812 06:16:33.052022 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000020 (ops 96-100)
I20260812 06:16:33.052064 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000021 (ops 101-105)
I20260812 06:16:33.052130 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000022 (ops 106-110)
I20260812 06:16:33.052173 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000023 (ops 111-114)
I20260812 06:16:33.052213 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000024 (ops 115-119)
I20260812 06:16:33.052254 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000025 (ops 120-124)
I20260812 06:16:33.052295 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000026 (ops 125-129)
I20260812 06:16:33.052335 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000027 (ops 130-134)
I20260812 06:16:33.082505 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: LogGCOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:16:33.083237 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=4.173312
I20260812 06:16:33.097167 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":5333393,"delete_count":0,"lbm_write_time_us":5743,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:16:33.097671 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling UndoDeltaBlockGCOp(54be331f6c784345a1afc034e943f98d): 482 bytes on disk
I20260812 06:16:33.098088 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: UndoDeltaBlockGCOp(54be331f6c784345a1afc034e943f98d) 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:33.098598 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=1.196750
I20260812 06:16:33.107996 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.009s	user 0.002s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":3191,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:16:33.108609 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:33.352402 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.244s	user 0.162s	sys 0.080s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123240,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1239,"lbm_read_time_us":17716,"lbm_reads_lt_1ms":875,"lbm_write_time_us":46432,"lbm_writes_lt_1ms":843,"mutex_wait_us":823,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":7168,"thread_start_us":84,"threads_started":1,"update_count":4000}
I20260812 06:16:33.353235 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=18.063937
I20260812 06:16:33.414436 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.061s	user 0.030s	sys 0.028s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28060,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:16:33.415191 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:33.427857 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4962,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.428377 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:33.602378 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.174s	user 0.126s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":12497,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36333,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":3000}
I20260812 06:16:33.603048 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=14.095187
I20260812 06:16:33.656388 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.053s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23421,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.656905 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:33.673955 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.674521 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:33.832083 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.157s	user 0.101s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":315,"lbm_read_time_us":10880,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28624,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:16:33.832707 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=14.095187
I20260812 06:16:33.885785 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.053s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23212,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.886409 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:34.039680 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.153s	user 0.108s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":415,"lbm_read_time_us":9808,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25606,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:16:34.040405 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=14.095187
I20260812 06:16:34.088238 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.048s	user 0.020s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21701,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:34.088771 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:34.119495 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.031s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.120232 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:34.300707 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.180s	user 0.116s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":245,"lbm_read_time_us":13570,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29743,"lbm_writes_lt_1ms":543,"mutex_wait_us":99,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":2500}
I20260812 06:16:34.301452 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=14.095187
I20260812 06:16:34.350383 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.049s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22516,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:34.350876 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:34.372005 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.021s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.372537 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:34.393283 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.021s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3842,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.393879 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushMRSOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:34.429790 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushMRSOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.036s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1086,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3726,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:34.430506 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling LogGCOp(54be331f6c784345a1afc034e943f98d): free 112692616 bytes of WAL
I20260812 06:16:34.430789 20534 log_reader.cc:385] T 54be331f6c784345a1afc034e943f98d: removed 11 log segments from log reader
I20260812 06:16:34.430855 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000028 (ops 135-139)
I20260812 06:16:34.430896 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000029 (ops 140-144)
I20260812 06:16:34.430920 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000030 (ops 145-149)
I20260812 06:16:34.430943 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000031 (ops 150-154)
I20260812 06:16:34.430974 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000032 (ops 155-159)
I20260812 06:16:34.431007 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000033 (ops 160-164)
I20260812 06:16:34.431035 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000034 (ops 165-169)
I20260812 06:16:34.431058 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000035 (ops 170-174)
I20260812 06:16:34.431088 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000036 (ops 175-179)
I20260812 06:16:34.431133 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000037 (ops 180-184)
I20260812 06:16:34.431159 20534 log.cc:1079] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: Deleting log segment in path: /tmp/dist-test-taskkCUhT_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515384167657-20088-0/minicluster-data/ts-0-root/wals/54be331f6c784345a1afc034e943f98d/wal-000000038 (ops 185-189)
I20260812 06:16:34.461300 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: LogGCOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:34.461880 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:34.493001 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.031s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.493551 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=2.188937
I20260812 06:16:34.504515 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.505097 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d): perf score=1.000000
I20260812 06:16:34.697772 20088 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.860s	user 1.804s	sys 0.185s
I20260812 06:16:34.754804 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: MajorDeltaCompactionOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.249s	user 0.161s	sys 0.086s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":16870,"lbm_reads_lt_1ms":871,"lbm_write_time_us":43589,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":4000}
I20260812 06:16:34.755483 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling UndoDeltaBlockGCOp(54be331f6c784345a1afc034e943f98d): 447 bytes on disk
I20260812 06:16:34.755944 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: UndoDeltaBlockGCOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:16:34.756520 20633 maintenance_manager.cc:419] P 7916d0e437074eea80357edba049a5b4: Scheduling FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d): perf score=14.095187
I20260812 06:16:34.816838 20088 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.119s	user 0.002s	sys 0.000s
I20260812 06:16:34.817349 20088 tablet_server.cc:179] TabletServer@127.19.158.1:0 shutting down...
I20260812 06:16:34.838976 20534 maintenance_manager.cc:643] P 7916d0e437074eea80357edba049a5b4: FlushDeltaMemStoresOp(54be331f6c784345a1afc034e943f98d) complete. Timing: real 0.082s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19802,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:34.839622 20088 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:34.839879 20088 tablet_replica.cc:333] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4: stopping tablet replica
I20260812 06:16:34.840008 20088 raft_consensus.cc:2243] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.840222 20088 raft_consensus.cc:2272] T 54be331f6c784345a1afc034e943f98d P 7916d0e437074eea80357edba049a5b4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.853988 20088 tablet_server.cc:196] TabletServer@127.19.158.1:0 shutdown complete.
I20260812 06:16:34.869220 20088 master.cc:562] Master@127.19.158.62:36975 shutting down...
I20260812 06:16:34.872488 20088 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.872674 20088 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.872727 20088 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3956fa3a3cec43b98a06989d9d1651cc: stopping tablet replica
I20260812 06:16:34.885296 20088 master.cc:584] Master@127.19.158.62:36975 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5386 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10799 ms total)

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