[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:25.591318  2754 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.176.190:35833
I20260812 06:17:25.592466  2754 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:25.593138  2754 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:25.600344  2761 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:25.600358  2760 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:25.600615  2764 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:25.600510  2754 server_base.cc:1061] running on GCE node
I20260812 06:17:25.601249  2754 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:25.601382  2754 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:25.601418  2754 hybrid_clock.cc:648] HybridClock initialized: now 1786515445601416 us; error 0 us; skew 500 ppm
I20260812 06:17:25.603559  2754 webserver.cc:533] Webserver started at http://127.2.176.190:37949/ using document root <none> and password file <none>
I20260812 06:17:25.604156  2754 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:25.604226  2754 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:25.604446  2754 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:25.606355  2754 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/master-0-root/instance:
uuid: "4878a97f0fd64029b1e6e7f8ea3cced8"
format_stamp: "Formatted at 2026-08-12 06:17:25 on dist-test-slave-8tdl"
I20260812 06:17:25.610257  2754 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:17:25.612748  2769 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:25.614070  2754 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:25.614192  2754 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/master-0-root
uuid: "4878a97f0fd64029b1e6e7f8ea3cced8"
format_stamp: "Formatted at 2026-08-12 06:17:25 on dist-test-slave-8tdl"
I20260812 06:17:25.614290  2754 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:25.632750  2754 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:25.633404  2754 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:25.633544  2754 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:25.641971  2754 rpc_server.cc:307] RPC server started. Bound to: 127.2.176.190:35833
I20260812 06:17:25.641986  2827 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.176.190:35833 every 8 connection(s)
I20260812 06:17:25.644529  2828 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:25.651052  2828 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8: Bootstrap starting.
I20260812 06:17:25.653661  2828 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:25.654804  2828 log.cc:826] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:25.656880  2828 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8: No bootstrap required, opened a new log
I20260812 06:17:25.660027  2828 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4878a97f0fd64029b1e6e7f8ea3cced8" member_type: VOTER }
I20260812 06:17:25.660269  2828 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:25.660363  2828 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4878a97f0fd64029b1e6e7f8ea3cced8, State: Initialized, Role: FOLLOWER
I20260812 06:17:25.661036  2828 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [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: "4878a97f0fd64029b1e6e7f8ea3cced8" member_type: VOTER }
I20260812 06:17:25.661226  2828 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:25.661310  2828 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:25.661470  2828 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:25.662410  2828 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4878a97f0fd64029b1e6e7f8ea3cced8" member_type: VOTER }
I20260812 06:17:25.662956  2828 leader_election.cc:304] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [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: 4878a97f0fd64029b1e6e7f8ea3cced8; no voters: 
I20260812 06:17:25.663343  2828 leader_election.cc:290] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:25.663499  2832 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:25.663790  2832 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 1 LEADER]: Becoming Leader. State: Replica: 4878a97f0fd64029b1e6e7f8ea3cced8, State: Running, Role: LEADER
I20260812 06:17:25.664247  2832 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [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: "4878a97f0fd64029b1e6e7f8ea3cced8" member_type: VOTER }
I20260812 06:17:25.664494  2828 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:25.666328  2833 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4878a97f0fd64029b1e6e7f8ea3cced8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4878a97f0fd64029b1e6e7f8ea3cced8" member_type: VOTER } }
I20260812 06:17:25.666471  2834 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4878a97f0fd64029b1e6e7f8ea3cced8. Latest consensus state: current_term: 1 leader_uuid: "4878a97f0fd64029b1e6e7f8ea3cced8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4878a97f0fd64029b1e6e7f8ea3cced8" member_type: VOTER } }
I20260812 06:17:25.666487  2833 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:25.666584  2834 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:25.666975  2846 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:25.667121  2754 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:25.669270  2846 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:25.674461  2846 catalog_manager.cc:1383] Generated new cluster ID: 69a9cdfb981c4fcabe33aece6694b140
I20260812 06:17:25.674571  2846 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:25.693991  2846 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:25.695315  2846 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:25.704972  2846 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8: Generated new TSK 0
I20260812 06:17:25.705819  2846 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:25.732095  2754 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:25.735365  2859 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:25.735515  2855 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:25.735729  2754 server_base.cc:1061] running on GCE node
W20260812 06:17:25.735526  2856 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:25.735985  2754 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:25.736058  2754 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:25.736083  2754 hybrid_clock.cc:648] HybridClock initialized: now 1786515445736082 us; error 0 us; skew 500 ppm
I20260812 06:17:25.740221  2754 webserver.cc:533] Webserver started at http://127.2.176.129:45809/ using document root <none> and password file <none>
I20260812 06:17:25.740487  2754 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:25.740561  2754 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:25.740656  2754 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:25.741161  2754 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/instance:
uuid: "b787dc994faa4b35a1dfb84603dbcea8"
format_stamp: "Formatted at 2026-08-12 06:17:25 on dist-test-slave-8tdl"
I20260812 06:17:25.742843  2754 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:25.743907  2864 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:25.744172  2754 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:25.744246  2754 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root
uuid: "b787dc994faa4b35a1dfb84603dbcea8"
format_stamp: "Formatted at 2026-08-12 06:17:25 on dist-test-slave-8tdl"
I20260812 06:17:25.744340  2754 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:25.753132  2754 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:25.753679  2754 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:25.754297  2754 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:25.755364  2754 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:25.755424  2754 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:25.755491  2754 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:25.755527  2754 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:25.762382  2754 rpc_server.cc:307] RPC server started. Bound to: 127.2.176.129:33869
I20260812 06:17:25.762655  2933 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.176.129:33869 every 8 connection(s)
I20260812 06:17:25.778381  2934 heartbeater.cc:344] Connected to a master server at 127.2.176.190:35833
I20260812 06:17:25.778808  2934 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:25.779389  2934 heartbeater.cc:507] Master 127.2.176.190:35833 requested a full tablet report, sending...
I20260812 06:17:25.781316  2788 ts_manager.cc:194] Registered new tserver with Master: b787dc994faa4b35a1dfb84603dbcea8 (127.2.176.129:33869)
I20260812 06:17:25.781423  2754 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018245782s
I20260812 06:17:25.782884  2788 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38898
I20260812 06:17:25.792608  2788 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38914:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:25.811843  2894 tablet_service.cc:1511] Processing CreateTablet for tablet 30f91cd6676a4fd0a5de645fbdc4c96c (DEFAULT_TABLE table=heavy-update-compaction-test [id=f6b385bfbe264bbda5f4d88c6c431a64]), partition=
I20260812 06:17:25.812440  2894 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 30f91cd6676a4fd0a5de645fbdc4c96c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:25.814945  2946 tablet_bootstrap.cc:492] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Bootstrap starting.
I20260812 06:17:25.816233  2946 tablet_bootstrap.cc:654] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:25.817597  2946 tablet_bootstrap.cc:492] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: No bootstrap required, opened a new log
I20260812 06:17:25.817727  2946 ts_tablet_manager.cc:1403] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:25.818246  2946 raft_consensus.cc:359] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b787dc994faa4b35a1dfb84603dbcea8" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 33869 } }
I20260812 06:17:25.818403  2946 raft_consensus.cc:385] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:25.818449  2946 raft_consensus.cc:740] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b787dc994faa4b35a1dfb84603dbcea8, State: Initialized, Role: FOLLOWER
I20260812 06:17:25.818598  2946 consensus_queue.cc:260] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [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: "b787dc994faa4b35a1dfb84603dbcea8" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 33869 } }
I20260812 06:17:25.818729  2946 raft_consensus.cc:399] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:25.818782  2946 raft_consensus.cc:493] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:25.818837  2946 raft_consensus.cc:3060] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:25.819610  2946 raft_consensus.cc:515] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b787dc994faa4b35a1dfb84603dbcea8" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 33869 } }
I20260812 06:17:25.819769  2946 leader_election.cc:304] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [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: b787dc994faa4b35a1dfb84603dbcea8; no voters: 
I20260812 06:17:25.820014  2946 leader_election.cc:290] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:25.820122  2949 raft_consensus.cc:2804] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:25.820376  2949 raft_consensus.cc:697] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 1 LEADER]: Becoming Leader. State: Replica: b787dc994faa4b35a1dfb84603dbcea8, State: Running, Role: LEADER
I20260812 06:17:25.820571  2949 consensus_queue.cc:237] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [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: "b787dc994faa4b35a1dfb84603dbcea8" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 33869 } }
I20260812 06:17:25.820647  2934 heartbeater.cc:499] Master 127.2.176.190:35833 was elected leader, sending a full tablet report...
I20260812 06:17:25.820385  2946 ts_tablet_manager.cc:1434] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:25.823423  2788 catalog_manager.cc:5719] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 reported cstate change: term changed from 0 to 1, leader changed from <none> to b787dc994faa4b35a1dfb84603dbcea8 (127.2.176.129). New cstate: current_term: 1 leader_uuid: "b787dc994faa4b35a1dfb84603dbcea8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b787dc994faa4b35a1dfb84603dbcea8" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 33869 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:25.891724  2754 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.016s	sys 0.012s
I20260812 06:17:26.014240  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushMRSOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=15.086190
I20260812 06:17:26.182708  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushMRSOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.168s	user 0.155s	sys 0.008s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":211,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":914,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40098,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":129,"threads_started":1,"update_count":1500}
I20260812 06:17:26.184218  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling LogGCOp(30f91cd6676a4fd0a5de645fbdc4c96c): free 8725963 bytes of WAL
I20260812 06:17:26.184610  2869 log_reader.cc:385] T 30f91cd6676a4fd0a5de645fbdc4c96c: removed 1 log segments from log reader
I20260812 06:17:26.184687  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000001 (ops 1-6)
I20260812 06:17:26.187129  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: LogGCOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:26.187515  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:26.209923  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.022s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5410,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.210408  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:26.228125  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6453,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.228786  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling UndoDeltaBlockGCOp(30f91cd6676a4fd0a5de645fbdc4c96c): 12308959 bytes on disk
I20260812 06:17:26.229440  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: UndoDeltaBlockGCOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:26.230013  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:26.386523  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.156s	user 0.115s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733842,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":890,"lbm_read_time_us":9657,"lbm_reads_lt_1ms":561,"lbm_write_time_us":28430,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":362,"threads_started":5,"update_count":2500}
I20260812 06:17:26.387305  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=10.126437
I20260812 06:17:26.433614  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.046s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15315,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.434103  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:26.446430  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.446923  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:26.575184  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.128s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":89,"lbm_read_time_us":8992,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24053,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2000}
I20260812 06:17:26.575812  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=10.126437
I20260812 06:17:26.617959  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.042s	user 0.018s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13057,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.618506  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:26.629796  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4104,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.630479  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:26.756053  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.125s	user 0.087s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":451,"lbm_read_time_us":8012,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23147,"lbm_writes_lt_1ms":443,"mutex_wait_us":85,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:17:26.756752  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=10.126437
I20260812 06:17:26.803031  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.046s	user 0.020s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15639,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.803661  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:26.815339  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.815868  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:26.983014  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.167s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":175,"lbm_read_time_us":11265,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27954,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27520,"update_count":2000}
I20260812 06:17:26.983714  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=10.126437
I20260812 06:17:27.020865  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.037s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14894,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.021493  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:27.130739  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.109s	user 0.088s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528783,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":839,"lbm_read_time_us":6445,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20498,"lbm_writes_lt_1ms":343,"mutex_wait_us":81,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.131466  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=10.126437
I20260812 06:17:27.178648  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.047s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17663,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.179277  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:27.190464  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.191210  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:27.317814  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.126s	user 0.090s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":9048,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22891,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:17:27.318490  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=10.126437
I20260812 06:17:27.363456  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.045s	user 0.020s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15485,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.364190  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:27.382370  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.383080  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushMRSOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:27.425360  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushMRSOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.042s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":399,"dirs.run_wall_time_us":1754,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2071,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:27.426249  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling LogGCOp(30f91cd6676a4fd0a5de645fbdc4c96c): free 115943112 bytes of WAL
I20260812 06:17:27.426491  2869 log_reader.cc:385] T 30f91cd6676a4fd0a5de645fbdc4c96c: removed 11 log segments from log reader
I20260812 06:17:27.426537  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000002 (ops 7-11)
I20260812 06:17:27.426587  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000003 (ops 12-16)
I20260812 06:17:27.426632  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000004 (ops 17-21)
I20260812 06:17:27.426692  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000005 (ops 22-26)
I20260812 06:17:27.426738  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000006 (ops 27-31)
I20260812 06:17:27.426779  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000007 (ops 32-36)
I20260812 06:17:27.426820  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000008 (ops 37-41)
I20260812 06:17:27.426860  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000009 (ops 42-46)
I20260812 06:17:27.426899  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000010 (ops 47-51)
I20260812 06:17:27.426937  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000011 (ops 52-56)
I20260812 06:17:27.426976  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000012 (ops 57-61)
I20260812 06:17:27.453107  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: LogGCOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:27.453683  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling UndoDeltaBlockGCOp(30f91cd6676a4fd0a5de645fbdc4c96c): 447 bytes on disk
I20260812 06:17:27.454452  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: UndoDeltaBlockGCOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.455031  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=3.181125
I20260812 06:17:27.469717  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.015s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4539,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:27.470252  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:27.480249  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.480805  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:27.692696  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.212s	user 0.143s	sys 0.062s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836365,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1246,"lbm_read_time_us":13255,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36164,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:17:27.693500  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=14.095187
I20260812 06:17:27.760496  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.067s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22670,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.761080  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:27.772233  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4178,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.772815  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:27.952811  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.179s	user 0.120s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":252,"lbm_read_time_us":11597,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30314,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:17:27.953545  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=14.095187
I20260812 06:17:28.014916  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.061s	user 0.037s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29180,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.015575  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:28.034282  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.018s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7052,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.034830  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:28.217109  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.182s	user 0.121s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":635,"lbm_read_time_us":12675,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30499,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:17:28.217798  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=14.095187
I20260812 06:17:28.277484  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.060s	user 0.039s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21068,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.278149  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:28.290056  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.290549  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:28.497239  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.206s	user 0.146s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":261,"lbm_read_time_us":14357,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35137,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:17:28.497952  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=11.118625
I20260812 06:17:28.534436  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.036s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15929,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:28.535140  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:28.554224  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.019s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5208,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.555037  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:28.736622  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.181s	user 0.136s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":806,"lbm_read_time_us":11587,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26686,"lbm_writes_lt_1ms":443,"mutex_wait_us":347,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:17:28.737416  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=10.126437
I20260812 06:17:28.785667  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.048s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18535,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:28.786339  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:28.797832  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4137,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.798451  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:28.942512  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.144s	user 0.116s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":486,"lbm_read_time_us":9681,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28990,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":107008,"update_count":2000}
I20260812 06:17:28.943449  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=10.126437
I20260812 06:17:28.989204  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.046s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17035,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.989751  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:29.002589  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.003286  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushMRSOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:29.036100  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushMRSOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":1901,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1701,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:29.037022  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling LogGCOp(30f91cd6676a4fd0a5de645fbdc4c96c): free 124710300 bytes of WAL
I20260812 06:17:29.037321  2869 log_reader.cc:385] T 30f91cd6676a4fd0a5de645fbdc4c96c: removed 12 log segments from log reader
I20260812 06:17:29.037386  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000013 (ops 62-66)
I20260812 06:17:29.037431  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000014 (ops 67-71)
I20260812 06:17:29.037452  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000015 (ops 72-76)
I20260812 06:17:29.037474  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000016 (ops 77-81)
I20260812 06:17:29.037503  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000017 (ops 82-86)
I20260812 06:17:29.037533  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000018 (ops 87-91)
I20260812 06:17:29.037567  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000019 (ops 92-96)
I20260812 06:17:29.037592  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000020 (ops 97-101)
I20260812 06:17:29.037621  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000021 (ops 102-106)
I20260812 06:17:29.037650  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000022 (ops 107-111)
I20260812 06:17:29.037675  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000023 (ops 112-116)
I20260812 06:17:29.037700  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000024 (ops 117-121)
I20260812 06:17:29.067968  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: LogGCOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:29.068423  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:29.092345  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.024s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4390,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.092878  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling UndoDeltaBlockGCOp(30f91cd6676a4fd0a5de645fbdc4c96c): 462 bytes on disk
I20260812 06:17:29.093283  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: UndoDeltaBlockGCOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.093767  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:29.104528  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.105218  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:29.287701  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.182s	user 0.153s	sys 0.027s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836375,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":740,"lbm_read_time_us":13220,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35605,"lbm_writes_lt_1ms":643,"mutex_wait_us":384,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":93,"threads_started":1,"update_count":3000}
I20260812 06:17:29.288858  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=14.095187
I20260812 06:17:29.340193  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.051s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21747,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.340729  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:29.353932  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5116,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.354595  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:29.523133  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.168s	user 0.124s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":10692,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30219,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:17:29.523959  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=14.095187
I20260812 06:17:29.579064  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.055s	user 0.051s	sys 0.000s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.579690  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:29.723729  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.144s	user 0.094s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":10473,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22133,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:29.724560  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=11.118625
I20260812 06:17:29.772470  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.047s	user 0.032s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20501,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:29.773005  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:29.796954  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.797622  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:29.807756  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3665,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.808288  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:30.018687  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.210s	user 0.128s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":4245,"lbm_read_time_us":11797,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34091,"lbm_writes_lt_1ms":543,"mutex_wait_us":2790,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:30.019734  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=14.095187
I20260812 06:17:30.069625  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.050s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21869,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.070230  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:30.083762  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4459,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.084544  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:30.245491  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.161s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":917,"lbm_read_time_us":9744,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32178,"lbm_writes_lt_1ms":543,"mutex_wait_us":365,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27392,"update_count":2500}
I20260812 06:17:30.246250  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=11.118625
I20260812 06:17:30.291313  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.045s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18586,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:30.291853  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:30.313431  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.021s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5130,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.313978  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:30.325017  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.325549  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:30.476747  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.151s	user 0.127s	sys 0.021s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":330,"lbm_read_time_us":10641,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31184,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:30.477500  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=10.126437
I20260812 06:17:30.524362  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.047s	user 0.041s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19494,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.524994  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:30.545436  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.020s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.546056  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushMRSOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:30.588646  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushMRSOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.042s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":326,"dirs.run_wall_time_us":2407,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2557,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":1408}
I20260812 06:17:30.589429  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling UndoDeltaBlockGCOp(30f91cd6676a4fd0a5de645fbdc4c96c): 483 bytes on disk
I20260812 06:17:30.589900  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: UndoDeltaBlockGCOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.590627  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=3.181125
I20260812 06:17:30.603713  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4615,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:30.604251  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling LogGCOp(30f91cd6676a4fd0a5de645fbdc4c96c): free 132571609 bytes of WAL
I20260812 06:17:30.604488  2869 log_reader.cc:385] T 30f91cd6676a4fd0a5de645fbdc4c96c: removed 13 log segments from log reader
I20260812 06:17:30.604543  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000025 (ops 122-126)
I20260812 06:17:30.604600  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000026 (ops 127-131)
I20260812 06:17:30.604637  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000027 (ops 132-136)
I20260812 06:17:30.604678  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000028 (ops 137-141)
I20260812 06:17:30.604717  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000029 (ops 142-146)
I20260812 06:17:30.604758  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000030 (ops 147-150)
I20260812 06:17:30.604801  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000031 (ops 151-155)
I20260812 06:17:30.604851  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000032 (ops 156-160)
I20260812 06:17:30.604892  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000033 (ops 161-164)
I20260812 06:17:30.604931  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000034 (ops 165-169)
I20260812 06:17:30.604971  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000035 (ops 170-174)
I20260812 06:17:30.605011  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000036 (ops 175-179)
I20260812 06:17:30.605050  2869 log.cc:1079] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/30f91cd6676a4fd0a5de645fbdc4c96c/wal-000000037 (ops 180-184)
I20260812 06:17:30.634923  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: LogGCOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:30.635403  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:30.649470  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.014s	user 0.007s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.650029  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:30.670980  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.021s	user 0.004s	sys 0.016s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3789,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.671651  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:30.900406  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.229s	user 0.158s	sys 0.070s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938894,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":739,"lbm_read_time_us":16425,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39217,"lbm_writes_lt_1ms":743,"mutex_wait_us":33,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:17:30.900928  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=14.095187
I20260812 06:17:30.964094  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.063s	user 0.034s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23415,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.964741  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=2.188937
I20260812 06:17:30.976218  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4398,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.976755  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=1.000000
I20260812 06:17:31.085772  2754 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.194s	user 1.871s	sys 0.171s
I20260812 06:17:31.148489  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: MajorDeltaCompactionOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.172s	user 0.101s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":196,"lbm_read_time_us":12455,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29883,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":77184,"update_count":2500}
I20260812 06:17:31.149093  2935 maintenance_manager.cc:419] P b787dc994faa4b35a1dfb84603dbcea8: Scheduling FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c): perf score=6.157687
I20260812 06:17:31.156397  2754 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.070s	user 0.002s	sys 0.000s
I20260812 06:17:31.157090  2754 tablet_server.cc:179] TabletServer@127.2.176.129:0 shutting down...
I20260812 06:17:31.175325  2869 maintenance_manager.cc:643] P b787dc994faa4b35a1dfb84603dbcea8: FlushDeltaMemStoresOp(30f91cd6676a4fd0a5de645fbdc4c96c) complete. Timing: real 0.026s	user 0.013s	sys 0.013s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11118,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:31.175983  2754 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:31.176452  2754 tablet_replica.cc:333] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8: stopping tablet replica
I20260812 06:17:31.176658  2754 raft_consensus.cc:2243] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:31.176867  2754 raft_consensus.cc:2272] T 30f91cd6676a4fd0a5de645fbdc4c96c P b787dc994faa4b35a1dfb84603dbcea8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:31.194455  2754 tablet_server.cc:196] TabletServer@127.2.176.129:0 shutdown complete.
I20260812 06:17:31.199678  2754 master.cc:562] Master@127.2.176.190:35833 shutting down...
I20260812 06:17:31.203620  2754 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:31.203809  2754 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:31.203866  2754 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4878a97f0fd64029b1e6e7f8ea3cced8: stopping tablet replica
I20260812 06:17:31.216568  2754 master.cc:584] Master@127.2.176.190:35833 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5719 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:31.323213  2754 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.176.190:40377
I20260812 06:17:31.323642  2754 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:31.326179  2974 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:31.326284  2754 server_base.cc:1061] running on GCE node
W20260812 06:17:31.326179  2972 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:31.326280  2969 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:31.326766  2754 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:31.326892  2754 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:31.326943  2754 hybrid_clock.cc:648] HybridClock initialized: now 1786515451326942 us; error 0 us; skew 500 ppm
I20260812 06:17:31.328190  2754 webserver.cc:533] Webserver started at http://127.2.176.190:40225/ using document root <none> and password file <none>
I20260812 06:17:31.328346  2754 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:31.328397  2754 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:31.328461  2754 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:31.328843  2754 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/master-0-root/instance:
uuid: "36c6fdc29ade411c8d20132049002f64"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-8tdl"
I20260812 06:17:31.330459  2754 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:31.331664  2979 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:31.331941  2754 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:31.332027  2754 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/master-0-root
uuid: "36c6fdc29ade411c8d20132049002f64"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-8tdl"
I20260812 06:17:31.332091  2754 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:31.362630  2754 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:31.363142  2754 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:31.368216  2754 rpc_server.cc:307] RPC server started. Bound to: 127.2.176.190:40377
I20260812 06:17:31.372581  3040 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.176.190:40377 every 8 connection(s)
I20260812 06:17:31.373131  3041 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:31.375175  3041 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64: Bootstrap starting.
I20260812 06:17:31.376086  3041 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:31.377269  3041 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64: No bootstrap required, opened a new log
I20260812 06:17:31.377748  3041 raft_consensus.cc:359] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "36c6fdc29ade411c8d20132049002f64" member_type: VOTER }
I20260812 06:17:31.377846  3041 raft_consensus.cc:385] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:31.377869  3041 raft_consensus.cc:740] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 36c6fdc29ade411c8d20132049002f64, State: Initialized, Role: FOLLOWER
I20260812 06:17:31.378036  3041 consensus_queue.cc:260] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [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: "36c6fdc29ade411c8d20132049002f64" member_type: VOTER }
I20260812 06:17:31.378109  3041 raft_consensus.cc:399] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:31.378165  3041 raft_consensus.cc:493] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:31.378247  3041 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:31.379251  3041 raft_consensus.cc:515] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "36c6fdc29ade411c8d20132049002f64" member_type: VOTER }
I20260812 06:17:31.379423  3041 leader_election.cc:304] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [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: 36c6fdc29ade411c8d20132049002f64; no voters: 
I20260812 06:17:31.379690  3041 leader_election.cc:290] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:31.379976  3045 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:31.380220  3041 sys_catalog.cc:565] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:31.380226  3045 raft_consensus.cc:697] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 1 LEADER]: Becoming Leader. State: Replica: 36c6fdc29ade411c8d20132049002f64, State: Running, Role: LEADER
I20260812 06:17:31.380414  3045 consensus_queue.cc:237] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [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: "36c6fdc29ade411c8d20132049002f64" member_type: VOTER }
I20260812 06:17:31.380909  3048 sys_catalog.cc:455] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 36c6fdc29ade411c8d20132049002f64. Latest consensus state: current_term: 1 leader_uuid: "36c6fdc29ade411c8d20132049002f64" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "36c6fdc29ade411c8d20132049002f64" member_type: VOTER } }
I20260812 06:17:31.381075  3048 sys_catalog.cc:458] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:31.381250  3047 sys_catalog.cc:455] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "36c6fdc29ade411c8d20132049002f64" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "36c6fdc29ade411c8d20132049002f64" member_type: VOTER } }
I20260812 06:17:31.381371  3047 sys_catalog.cc:458] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:31.381759  3054 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:31.382809  3054 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:31.383014  2754 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:31.385126  3054 catalog_manager.cc:1383] Generated new cluster ID: dfa02b5d006849bd97e7e44835c00458
I20260812 06:17:31.385211  3054 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:31.392186  3054 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:31.392774  3054 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:31.405325  3054 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64: Generated new TSK 0
I20260812 06:17:31.405548  3054 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:31.415663  2754 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:31.418586  3068 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:31.418753  3064 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:31.418586  3065 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:31.418648  2754 server_base.cc:1061] running on GCE node
I20260812 06:17:31.419188  2754 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:31.419257  2754 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:31.419283  2754 hybrid_clock.cc:648] HybridClock initialized: now 1786515451419283 us; error 0 us; skew 500 ppm
I20260812 06:17:31.420333  2754 webserver.cc:533] Webserver started at http://127.2.176.129:37085/ using document root <none> and password file <none>
I20260812 06:17:31.420559  2754 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:31.420645  2754 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:31.420769  2754 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:31.421217  2754 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/instance:
uuid: "e9cd12e6ad6f49e39adee0cdeea26cea"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-8tdl"
I20260812 06:17:31.422964  2754 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:31.424192  3074 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:31.424492  2754 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:31.424584  2754 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root
uuid: "e9cd12e6ad6f49e39adee0cdeea26cea"
format_stamp: "Formatted at 2026-08-12 06:17:31 on dist-test-slave-8tdl"
I20260812 06:17:31.424674  2754 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:31.443214  2754 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:31.443671  2754 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:31.444024  2754 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:31.444541  2754 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:31.444598  2754 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:31.444656  2754 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:31.444698  2754 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:31.449465  2754 rpc_server.cc:307] RPC server started. Bound to: 127.2.176.129:37995
I20260812 06:17:31.451109  3147 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.176.129:37995 every 8 connection(s)
I20260812 06:17:31.460877  3148 heartbeater.cc:344] Connected to a master server at 127.2.176.190:40377
I20260812 06:17:31.461059  3148 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:31.461400  3148 heartbeater.cc:507] Master 127.2.176.190:40377 requested a full tablet report, sending...
I20260812 06:17:31.462319  2999 ts_manager.cc:194] Registered new tserver with Master: e9cd12e6ad6f49e39adee0cdeea26cea (127.2.176.129:37995)
I20260812 06:17:31.462734  2754 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012518802s
I20260812 06:17:31.463320  2999 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36392
I20260812 06:17:31.471855  2999 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36406:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:31.481876  3104 tablet_service.cc:1511] Processing CreateTablet for tablet f2412399d6be4d50b7718378e7fe8ec0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8b9edec0e144427998fd884cfe461301]), partition=
I20260812 06:17:31.482236  3104 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f2412399d6be4d50b7718378e7fe8ec0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:31.484404  3163 tablet_bootstrap.cc:492] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Bootstrap starting.
I20260812 06:17:31.485360  3163 tablet_bootstrap.cc:654] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:31.486624  3163 tablet_bootstrap.cc:492] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: No bootstrap required, opened a new log
I20260812 06:17:31.486776  3163 ts_tablet_manager.cc:1403] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:31.487320  3163 raft_consensus.cc:359] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e9cd12e6ad6f49e39adee0cdeea26cea" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 37995 } }
I20260812 06:17:31.487478  3163 raft_consensus.cc:385] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:31.487535  3163 raft_consensus.cc:740] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e9cd12e6ad6f49e39adee0cdeea26cea, State: Initialized, Role: FOLLOWER
I20260812 06:17:31.487681  3163 consensus_queue.cc:260] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [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: "e9cd12e6ad6f49e39adee0cdeea26cea" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 37995 } }
I20260812 06:17:31.487775  3163 raft_consensus.cc:399] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:31.487820  3163 raft_consensus.cc:493] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:31.487870  3163 raft_consensus.cc:3060] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:31.488790  3163 raft_consensus.cc:515] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e9cd12e6ad6f49e39adee0cdeea26cea" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 37995 } }
I20260812 06:17:31.488930  3163 leader_election.cc:304] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [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: e9cd12e6ad6f49e39adee0cdeea26cea; no voters: 
I20260812 06:17:31.489115  3163 leader_election.cc:290] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:31.489283  3165 raft_consensus.cc:2804] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:31.489446  3165 raft_consensus.cc:697] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 1 LEADER]: Becoming Leader. State: Replica: e9cd12e6ad6f49e39adee0cdeea26cea, State: Running, Role: LEADER
I20260812 06:17:31.489492  3148 heartbeater.cc:499] Master 127.2.176.190:40377 was elected leader, sending a full tablet report...
I20260812 06:17:31.489645  3165 consensus_queue.cc:237] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [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: "e9cd12e6ad6f49e39adee0cdeea26cea" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 37995 } }
I20260812 06:17:31.489450  3163 ts_tablet_manager.cc:1434] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:31.491627  2999 catalog_manager.cc:5719] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea reported cstate change: term changed from 0 to 1, leader changed from <none> to e9cd12e6ad6f49e39adee0cdeea26cea (127.2.176.129). New cstate: current_term: 1 leader_uuid: "e9cd12e6ad6f49e39adee0cdeea26cea" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e9cd12e6ad6f49e39adee0cdeea26cea" member_type: VOTER last_known_addr { host: "127.2.176.129" port: 37995 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:31.553119  2754 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.019s	sys 0.004s
I20260812 06:17:31.701674  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushMRSOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=19.054940
I20260812 06:17:31.878129  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushMRSOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.176s	user 0.125s	sys 0.047s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":1221,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42126,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:31.879098  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling LogGCOp(f2412399d6be4d50b7718378e7fe8ec0): free 20743880 bytes of WAL
I20260812 06:17:31.879415  3079 log_reader.cc:385] T f2412399d6be4d50b7718378e7fe8ec0: removed 2 log segments from log reader
I20260812 06:17:31.879465  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000001 (ops 1-6)
I20260812 06:17:31.879498  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000002 (ops 7-11)
I20260812 06:17:31.884155  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: LogGCOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:31.884560  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling UndoDeltaBlockGCOp(f2412399d6be4d50b7718378e7fe8ec0): 16411397 bytes on disk
I20260812 06:17:31.885089  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: UndoDeltaBlockGCOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:17:31.885500  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:31.896544  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.897054  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:32.071615  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.174s	user 0.131s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":698,"lbm_read_time_us":12491,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28153,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"thread_start_us":381,"threads_started":5,"update_count":2000}
I20260812 06:17:32.072324  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:32.119062  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.047s	user 0.014s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18694,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.119573  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:32.132692  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.133479  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:32.271127  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.137s	user 0.122s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":150,"lbm_read_time_us":9455,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27341,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:32.271906  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:32.317719  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.046s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16720,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.318289  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:32.330564  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.331485  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:32.457720  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.126s	user 0.095s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":353,"lbm_read_time_us":8575,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24097,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":48768,"update_count":2000}
I20260812 06:17:32.458377  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:32.515861  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.057s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20402,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.517012  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:32.531554  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4952,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.532039  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:32.657987  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.126s	user 0.093s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1115,"lbm_read_time_us":9241,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23616,"lbm_writes_lt_1ms":443,"mutex_wait_us":122,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:17:32.659029  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:32.708666  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.049s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17182,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.709270  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:32.720454  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.721143  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:32.883596  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.162s	user 0.118s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1015,"lbm_read_time_us":13090,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23942,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:17:32.884297  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:32.926605  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.042s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15055,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.927209  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:32.939157  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4366,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.939807  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:33.075799  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.136s	user 0.116s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":9658,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26624,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2000}
I20260812 06:17:33.076485  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:33.126565  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.050s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17695,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.127143  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:33.140412  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.141268  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushMRSOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:33.174382  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushMRSOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.033s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":293,"dirs.run_wall_time_us":1702,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1484,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:33.175129  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling LogGCOp(f2412399d6be4d50b7718378e7fe8ec0): free 115943176 bytes of WAL
I20260812 06:17:33.175364  3079 log_reader.cc:385] T f2412399d6be4d50b7718378e7fe8ec0: removed 11 log segments from log reader
I20260812 06:17:33.175408  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000003 (ops 12-16)
I20260812 06:17:33.175441  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000004 (ops 17-21)
I20260812 06:17:33.175513  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000005 (ops 22-26)
I20260812 06:17:33.175544  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000006 (ops 27-31)
I20260812 06:17:33.175563  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000007 (ops 32-36)
I20260812 06:17:33.175580  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000008 (ops 37-41)
I20260812 06:17:33.175638  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000009 (ops 42-46)
I20260812 06:17:33.175673  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000010 (ops 47-51)
I20260812 06:17:33.175715  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000011 (ops 52-56)
I20260812 06:17:33.175753  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000012 (ops 57-61)
I20260812 06:17:33.175791  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000013 (ops 62-66)
I20260812 06:17:33.204818  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: LogGCOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:33.205346  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling UndoDeltaBlockGCOp(f2412399d6be4d50b7718378e7fe8ec0): 447 bytes on disk
I20260812 06:17:33.206054  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: UndoDeltaBlockGCOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.206825  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=3.181125
I20260812 06:17:33.228437  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.021s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7356,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:33.228955  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:33.240495  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4053,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.241062  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:33.430241  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.189s	user 0.135s	sys 0.050s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":583,"lbm_read_time_us":13938,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35547,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":78464,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:17:33.431025  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=14.095187
I20260812 06:17:33.484506  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.053s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21030,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.485118  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:33.498624  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.499348  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:33.669873  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.170s	user 0.127s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1025,"lbm_read_time_us":11281,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33989,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:17:33.670796  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=11.118625
I20260812 06:17:33.708575  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.038s	user 0.031s	sys 0.005s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16604,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:33.709215  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:33.723228  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.014s	user 0.002s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4966,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.723816  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:33.859036  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.135s	user 0.091s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":254,"lbm_read_time_us":10614,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25487,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:17:33.862839  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=11.118625
I20260812 06:17:33.910247  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.047s	user 0.012s	sys 0.032s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14984,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:33.911012  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:33.921572  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4010,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.922202  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:34.078917  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.156s	user 0.103s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":356,"lbm_read_time_us":11960,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23720,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2000}
I20260812 06:17:34.079859  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:34.119055  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.039s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17918,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.119567  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:34.134899  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.135505  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:34.270773  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.135s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1116,"lbm_read_time_us":8046,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27868,"lbm_writes_lt_1ms":443,"mutex_wait_us":399,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":37888,"update_count":2000}
I20260812 06:17:34.274103  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:34.306000  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.032s	user 0.021s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13676,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.306712  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:34.321884  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5697,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.322511  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:34.455164  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.132s	user 0.093s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":751,"lbm_read_time_us":9708,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26088,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:17:34.456202  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:34.493503  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.037s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16224,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.494021  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:34.507481  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.508068  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:34.646402  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.138s	user 0.110s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":255,"lbm_read_time_us":9896,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25837,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23552,"update_count":2000}
I20260812 06:17:34.647145  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:34.702301  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.055s	user 0.021s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18771,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.703054  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:34.715281  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.715780  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushMRSOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:34.760154  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushMRSOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.044s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1797,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2199,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:34.760918  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling LogGCOp(f2412399d6be4d50b7718378e7fe8ec0): free 121006381 bytes of WAL
I20260812 06:17:34.761160  3079 log_reader.cc:385] T f2412399d6be4d50b7718378e7fe8ec0: removed 12 log segments from log reader
I20260812 06:17:34.761204  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000014 (ops 67-71)
I20260812 06:17:34.761235  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000015 (ops 72-76)
I20260812 06:17:34.761300  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000016 (ops 77-80)
I20260812 06:17:34.761343  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000017 (ops 81-85)
I20260812 06:17:34.761385  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000018 (ops 86-90)
I20260812 06:17:34.761425  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000019 (ops 91-95)
I20260812 06:17:34.761467  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000020 (ops 96-100)
I20260812 06:17:34.761502  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000021 (ops 101-105)
I20260812 06:17:34.761538  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000022 (ops 106-110)
I20260812 06:17:34.761576  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000023 (ops 111-115)
I20260812 06:17:34.761615  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000024 (ops 116-120)
I20260812 06:17:34.761652  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000025 (ops 121-125)
I20260812 06:17:34.789124  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: LogGCOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:34.789662  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling UndoDeltaBlockGCOp(f2412399d6be4d50b7718378e7fe8ec0): 481 bytes on disk
I20260812 06:17:34.790285  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: UndoDeltaBlockGCOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:34.791078  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=3.181125
I20260812 06:17:34.809689  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6759,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:34.810156  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:34.820518  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3724,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.821065  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:35.043038  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.222s	user 0.128s	sys 0.092s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1004,"lbm_read_time_us":15938,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35175,"lbm_writes_lt_1ms":643,"mutex_wait_us":382,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":131,"threads_started":1,"update_count":3000}
I20260812 06:17:35.044119  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=14.095187
I20260812 06:17:35.093137  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.049s	user 0.042s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21185,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:35.093982  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:35.113651  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.114431  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:35.290889  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.176s	user 0.126s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":877,"lbm_read_time_us":11645,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28440,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:17:35.291886  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=14.095187
I20260812 06:17:35.359467  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.067s	user 0.031s	sys 0.035s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27393,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.360205  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:35.379088  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":500}
I20260812 06:17:35.379652  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:35.563458  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.184s	user 0.124s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":384,"lbm_read_time_us":12780,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30440,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:35.564126  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=14.095187
I20260812 06:17:35.620507  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.056s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19688,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:35.621271  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:35.639447  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.018s	user 0.001s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.639978  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:35.838754  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.199s	user 0.125s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":397,"lbm_read_time_us":12440,"lbm_reads_lt_1ms":568,"lbm_write_time_us":35006,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:17:35.839342  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=14.095187
I20260812 06:17:35.898559  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.059s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25490,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.899250  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:35.921857  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.022s	user 0.012s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4321,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.922729  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:36.134084  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.211s	user 0.140s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":999,"lbm_read_time_us":17004,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27813,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:17:36.134766  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=14.095187
I20260812 06:17:36.191324  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.056s	user 0.037s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22990,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.191850  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:36.203125  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.011s	user 0.006s	sys 0.004s 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:17:36.203625  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:36.398584  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.195s	user 0.143s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":393,"lbm_read_time_us":11640,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31056,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:17:36.399240  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=14.095187
I20260812 06:17:36.454665  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.055s	user 0.041s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24073,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.455312  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=2.188937
I20260812 06:17:36.467834  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.468393  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushMRSOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:36.502645  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushMRSOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.034s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1548,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2048,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:36.503477  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling LogGCOp(f2412399d6be4d50b7718378e7fe8ec0): free 140885711 bytes of WAL
I20260812 06:17:36.503717  3079 log_reader.cc:385] T f2412399d6be4d50b7718378e7fe8ec0: removed 14 log segments from log reader
I20260812 06:17:36.503762  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000026 (ops 126-130)
I20260812 06:17:36.503793  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000027 (ops 131-135)
I20260812 06:17:36.503835  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000028 (ops 136-140)
I20260812 06:17:36.503883  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000029 (ops 141-144)
I20260812 06:17:36.503902  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000030 (ops 145-149)
I20260812 06:17:36.503955  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000031 (ops 150-154)
I20260812 06:17:36.504001  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000032 (ops 155-158)
I20260812 06:17:36.504045  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000033 (ops 159-163)
I20260812 06:17:36.504078  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000034 (ops 164-168)
I20260812 06:17:36.504139  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000035 (ops 169-172)
I20260812 06:17:36.504176  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000036 (ops 173-177)
I20260812 06:17:36.504213  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000037 (ops 178-182)
I20260812 06:17:36.504251  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000038 (ops 183-187)
I20260812 06:17:36.504289  3079 log.cc:1079] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: Deleting log segment in path: /tmp/dist-test-taskRib2pG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515445579780-2754-0/minicluster-data/ts-0-root/wals/f2412399d6be4d50b7718378e7fe8ec0/wal-000000039 (ops 188-192)
I20260812 06:17:36.540156  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: LogGCOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.036s	user 0.000s	sys 0.035s Metrics: {}
I20260812 06:17:36.540648  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling UndoDeltaBlockGCOp(f2412399d6be4d50b7718378e7fe8ec0): 492 bytes on disk
I20260812 06:17:36.541167  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: UndoDeltaBlockGCOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:17:36.541730  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=5.165500
I20260812 06:17:36.568658  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.027s	user 0.007s	sys 0.017s Metrics: {"bytes_written":6892305,"delete_count":0,"lbm_write_time_us":11093,"lbm_writes_lt_1ms":171,"reinsert_count":0,"update_count":840}
I20260812 06:17:36.569258  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:36.576786  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {"bytes_written":1312952,"delete_count":0,"lbm_write_time_us":1454,"lbm_writes_lt_1ms":35,"reinsert_count":0,"update_count":160}
I20260812 06:17:36.577389  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=1.000000
I20260812 06:17:36.730866  2754 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.178s	user 1.861s	sys 0.143s
I20260812 06:17:36.804781  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: MajorDeltaCompactionOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.227s	user 0.136s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979685,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16946,"lbm_reads_lt_1ms":770,"lbm_write_time_us":40145,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":3500}
I20260812 06:17:36.805382  3149 maintenance_manager.cc:419] P e9cd12e6ad6f49e39adee0cdeea26cea: Scheduling FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0): perf score=10.126437
I20260812 06:17:36.825139  2754 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.001s	sys 0.000s
I20260812 06:17:36.825827  2754 tablet_server.cc:179] TabletServer@127.2.176.129:0 shutting down...
I20260812 06:17:36.858008  3079 maintenance_manager.cc:643] P e9cd12e6ad6f49e39adee0cdeea26cea: FlushDeltaMemStoresOp(f2412399d6be4d50b7718378e7fe8ec0) complete. Timing: real 0.052s	user 0.025s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17892,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.858834  2754 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:36.859098  2754 tablet_replica.cc:333] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea: stopping tablet replica
I20260812 06:17:36.859294  2754 raft_consensus.cc:2243] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:36.859547  2754 raft_consensus.cc:2272] T f2412399d6be4d50b7718378e7fe8ec0 P e9cd12e6ad6f49e39adee0cdeea26cea [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:36.865638  2754 tablet_server.cc:196] TabletServer@127.2.176.129:0 shutdown complete.
I20260812 06:17:36.869222  2754 master.cc:562] Master@127.2.176.190:40377 shutting down...
I20260812 06:17:36.873286  2754 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:36.873543  2754 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:36.873659  2754 tablet_replica.cc:333] T 00000000000000000000000000000000 P 36c6fdc29ade411c8d20132049002f64: stopping tablet replica
I20260812 06:17:36.886541  2754 master.cc:584] Master@127.2.176.190:40377 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5665 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11385 ms total)

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