[==========] 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:09.358358  5866 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.186.190:44717
I20260812 06:17:09.359413  5866 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:09.360103  5866 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.366642  5873 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:09.366611  5872 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:09.366839  5866 server_base.cc:1061] running on GCE node
W20260812 06:17:09.366916  5875 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:09.367374  5866 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.367479  5866 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:09.367522  5866 hybrid_clock.cc:648] HybridClock initialized: now 1786515429367519 us; error 0 us; skew 500 ppm
I20260812 06:17:09.369385  5866 webserver.cc:533] Webserver started at http://127.5.186.190:40301/ using document root <none> and password file <none>
I20260812 06:17:09.369995  5866 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.370059  5866 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.370301  5866 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.371975  5866 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/master-0-root/instance:
uuid: "1d0fef5c6a5b42a1ac66e5774a323228"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-vq2q"
I20260812 06:17:09.375569  5866 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.004s
I20260812 06:17:09.377709  5880 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:09.378729  5866 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:09.378839  5866 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/master-0-root
uuid: "1d0fef5c6a5b42a1ac66e5774a323228"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-vq2q"
I20260812 06:17:09.378948  5866 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-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:09.399948  5866 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.400573  5866 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:09.400725  5866 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.408217  5866 rpc_server.cc:307] RPC server started. Bound to: 127.5.186.190:44717
I20260812 06:17:09.408226  5940 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.186.190:44717 every 8 connection(s)
I20260812 06:17:09.410653  5941 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:09.416296  5941 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228: Bootstrap starting.
I20260812 06:17:09.419253  5941 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.420194  5941 log.cc:826] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:09.422102  5941 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228: No bootstrap required, opened a new log
I20260812 06:17:09.425307  5941 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d0fef5c6a5b42a1ac66e5774a323228" member_type: VOTER }
I20260812 06:17:09.425494  5941 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.425545  5941 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1d0fef5c6a5b42a1ac66e5774a323228, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.426415  5941 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [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: "1d0fef5c6a5b42a1ac66e5774a323228" member_type: VOTER }
I20260812 06:17:09.426571  5941 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.426620  5941 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.426712  5941 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.454952  5941 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d0fef5c6a5b42a1ac66e5774a323228" member_type: VOTER }
I20260812 06:17:09.455637  5941 leader_election.cc:304] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [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: 1d0fef5c6a5b42a1ac66e5774a323228; no voters: 
I20260812 06:17:09.456113  5941 leader_election.cc:290] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.456300  5945 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.456559  5945 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 1 LEADER]: Becoming Leader. State: Replica: 1d0fef5c6a5b42a1ac66e5774a323228, State: Running, Role: LEADER
I20260812 06:17:09.457077  5945 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [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: "1d0fef5c6a5b42a1ac66e5774a323228" member_type: VOTER }
I20260812 06:17:09.457391  5941 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:09.459312  5947 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1d0fef5c6a5b42a1ac66e5774a323228. Latest consensus state: current_term: 1 leader_uuid: "1d0fef5c6a5b42a1ac66e5774a323228" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d0fef5c6a5b42a1ac66e5774a323228" member_type: VOTER } }
I20260812 06:17:09.459450  5947 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.459743  5946 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1d0fef5c6a5b42a1ac66e5774a323228" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d0fef5c6a5b42a1ac66e5774a323228" member_type: VOTER } }
I20260812 06:17:09.459838  5946 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.460685  5958 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:09.460945  5866 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:09.463045  5958 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:09.467993  5958 catalog_manager.cc:1383] Generated new cluster ID: a89ebffff6c64fc3b89e70303f55b2b7
I20260812 06:17:09.468056  5958 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:09.489610  5958 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:09.490804  5958 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:09.509073  5958 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228: Generated new TSK 0
I20260812 06:17:09.509932  5958 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:09.526212  5866 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.529057  5969 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:09.529040  5968 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:09.529035  5972 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:09.529381  5866 server_base.cc:1061] running on GCE node
I20260812 06:17:09.529574  5866 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.529618  5866 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:09.529632  5866 hybrid_clock.cc:648] HybridClock initialized: now 1786515429529632 us; error 0 us; skew 500 ppm
I20260812 06:17:09.530619  5866 webserver.cc:533] Webserver started at http://127.5.186.129:40515/ using document root <none> and password file <none>
I20260812 06:17:09.530795  5866 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.530853  5866 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.530941  5866 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.531334  5866 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/instance:
uuid: "71a5619ad0c24d46b66cd3a9260e260f"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-vq2q"
I20260812 06:17:09.532882  5866 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:09.533922  5977 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:09.534210  5866 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:09.534298  5866 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root
uuid: "71a5619ad0c24d46b66cd3a9260e260f"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-vq2q"
I20260812 06:17:09.534379  5866 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-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:09.574656  5866 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.575138  5866 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.575716  5866 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:09.576828  5866 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:09.576894  5866 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.576957  5866 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:09.576979  5866 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.583328  5866 rpc_server.cc:307] RPC server started. Bound to: 127.5.186.129:36955
I20260812 06:17:09.583534  6049 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.186.129:36955 every 8 connection(s)
I20260812 06:17:09.596858  6051 heartbeater.cc:344] Connected to a master server at 127.5.186.190:44717
I20260812 06:17:09.597127  6051 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:09.597645  6051 heartbeater.cc:507] Master 127.5.186.190:44717 requested a full tablet report, sending...
I20260812 06:17:09.599330  5902 ts_manager.cc:194] Registered new tserver with Master: 71a5619ad0c24d46b66cd3a9260e260f (127.5.186.129:36955)
I20260812 06:17:09.599818  5866 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015641451s
I20260812 06:17:09.600618  5902 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60732
I20260812 06:17:09.610327  5902 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60736:
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:09.626365  6011 tablet_service.cc:1511] Processing CreateTablet for tablet cd50c96cc8b5432ba9fe00ee422521b7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7b97d0b5edb044988bfbd23958023150]), partition=
I20260812 06:17:09.626847  6011 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cd50c96cc8b5432ba9fe00ee422521b7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:09.629376  6067 tablet_bootstrap.cc:492] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Bootstrap starting.
I20260812 06:17:09.630705  6067 tablet_bootstrap.cc:654] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.632496  6067 tablet_bootstrap.cc:492] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: No bootstrap required, opened a new log
I20260812 06:17:09.632718  6067 ts_tablet_manager.cc:1403] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:09.633700  6067 raft_consensus.cc:359] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71a5619ad0c24d46b66cd3a9260e260f" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36955 } }
I20260812 06:17:09.633929  6067 raft_consensus.cc:385] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.633988  6067 raft_consensus.cc:740] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 71a5619ad0c24d46b66cd3a9260e260f, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.634197  6067 consensus_queue.cc:260] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [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: "71a5619ad0c24d46b66cd3a9260e260f" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36955 } }
I20260812 06:17:09.634296  6067 raft_consensus.cc:399] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.634344  6067 raft_consensus.cc:493] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.634397  6067 raft_consensus.cc:3060] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.712656  6067 raft_consensus.cc:515] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71a5619ad0c24d46b66cd3a9260e260f" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36955 } }
I20260812 06:17:09.713096  6067 leader_election.cc:304] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [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: 71a5619ad0c24d46b66cd3a9260e260f; no voters: 
I20260812 06:17:09.713570  6067 leader_election.cc:290] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.713766  6069 raft_consensus.cc:2804] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.713999  6069 raft_consensus.cc:697] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 1 LEADER]: Becoming Leader. State: Replica: 71a5619ad0c24d46b66cd3a9260e260f, State: Running, Role: LEADER
I20260812 06:17:09.714100  6067 ts_tablet_manager.cc:1434] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Time spent starting tablet: real 0.081s	user 0.005s	sys 0.000s
I20260812 06:17:09.714246  6069 consensus_queue.cc:237] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [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: "71a5619ad0c24d46b66cd3a9260e260f" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36955 } }
I20260812 06:17:09.714489  6051 heartbeater.cc:499] Master 127.5.186.190:44717 was elected leader, sending a full tablet report...
I20260812 06:17:09.717698  5902 catalog_manager.cc:5719] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f reported cstate change: term changed from 0 to 1, leader changed from <none> to 71a5619ad0c24d46b66cd3a9260e260f (127.5.186.129). New cstate: current_term: 1 leader_uuid: "71a5619ad0c24d46b66cd3a9260e260f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71a5619ad0c24d46b66cd3a9260e260f" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36955 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:09.784550  5866 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.016s	sys 0.014s
I20260812 06:17:09.835296  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushMRSOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=6.156503
I20260812 06:17:10.017956  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushMRSOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.182s	user 0.096s	sys 0.031s Metrics: {"bytes_written":9517852,"cfile_init":1,"compiler_manager_pool.queue_time_us":462,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":42590,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":23740,"lbm_writes_lt_1ms":389,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"spinlock_wait_cycles":201984,"thread_start_us":191,"threads_started":1,"update_count":1160}
I20260812 06:17:10.019380  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=6.157687
I20260812 06:17:10.096603  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.077s	user 0.011s	sys 0.004s Metrics: {"bytes_written":7302553,"delete_count":0,"lbm_write_time_us":6068,"lbm_writes_lt_1ms":181,"reinsert_count":0,"update_count":890}
I20260812 06:17:10.097229  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling UndoDeltaBlockGCOp(cd50c96cc8b5432ba9fe00ee422521b7): 4103815 bytes on disk
I20260812 06:17:10.098048  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: UndoDeltaBlockGCOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.098533  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=6.157687
I20260812 06:17:10.144052  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.045s	user 0.013s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":7537,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:10.144583  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:10.244946  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.100s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3394,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.245551  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=8.142062
I20260812 06:17:10.348709  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.103s	user 0.010s	sys 0.017s Metrics: {"bytes_written":10051164,"delete_count":0,"lbm_write_time_us":11901,"lbm_writes_lt_1ms":248,"reinsert_count":0,"update_count":1225}
I20260812 06:17:10.349442  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=8.142062
I20260812 06:17:10.383242  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.034s	user 0.014s	sys 0.009s Metrics: {"bytes_written":10051172,"delete_count":0,"lbm_write_time_us":10531,"lbm_writes_lt_1ms":248,"reinsert_count":0,"update_count":1225}
I20260812 06:17:10.383762  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:10.393518  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.394053  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:10.721392  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.327s	user 0.232s	sys 0.084s Metrics: {"cfile_cache_miss":1337,"cfile_cache_miss_bytes":57471706,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":7,"delta_iterators_relevant":7,"dirs.queue_time_us":887,"lbm_read_time_us":20126,"lbm_reads_lt_1ms":1373,"lbm_write_time_us":57067,"lbm_writes_lt_1ms":1343,"peak_mem_usage":162528476,"reinsert_count":0,"thread_start_us":604,"threads_started":6,"update_count":6500}
I20260812 06:17:10.721967  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=26.001437
I20260812 06:17:10.870669  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.149s	user 0.031s	sys 0.040s Metrics: {"bytes_written":28717138,"delete_count":0,"lbm_write_time_us":32403,"lbm_writes_lt_1ms":703,"reinsert_count":0,"update_count":3500}
I20260812 06:17:10.871183  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=11.118625
I20260812 06:17:10.913040  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.042s	user 0.026s	sys 0.011s Metrics: {"bytes_written":13168993,"delete_count":0,"lbm_write_time_us":12287,"lbm_writes_lt_1ms":324,"reinsert_count":0,"update_count":1605}
I20260812 06:17:10.913682  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:10.927332  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.013s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3651384,"delete_count":0,"lbm_write_time_us":3182,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:10.927827  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:10.937067  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3327,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.937605  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:11.249985  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.312s	user 0.217s	sys 0.096s Metrics: {"cfile_cache_miss":1234,"cfile_cache_miss_bytes":53368891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":580,"lbm_read_time_us":21649,"lbm_reads_lt_1ms":1274,"lbm_write_time_us":57906,"lbm_writes_lt_1ms":1243,"peak_mem_usage":150101904,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":361,"threads_started":5,"update_count":6000}
I20260812 06:17:11.250571  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=22.032687
I20260812 06:17:11.323742  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.072s	user 0.034s	sys 0.024s Metrics: {"bytes_written":24614723,"delete_count":0,"lbm_write_time_us":26680,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:17:11.324343  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=6.157687
I20260812 06:17:11.381911  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.057s	user 0.012s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":7698,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:11.382423  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=3.181125
I20260812 06:17:11.401796  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.019s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4640,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:11.402297  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:11.415581  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4766,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:11.416184  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushMRSOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:11.455981  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushMRSOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.040s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1439520,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1403,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1851,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":35}
I20260812 06:17:11.456876  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling LogGCOp(cd50c96cc8b5432ba9fe00ee422521b7): free 145454221 bytes of WAL
I20260812 06:17:11.457211  5983 log_reader.cc:385] T cd50c96cc8b5432ba9fe00ee422521b7: removed 14 log segments from log reader
I20260812 06:17:11.457273  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000001 (ops 1-6)
I20260812 06:17:11.457338  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000002 (ops 7-11)
I20260812 06:17:11.457376  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000003 (ops 12-16)
I20260812 06:17:11.457396  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000004 (ops 17-21)
I20260812 06:17:11.457427  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000005 (ops 22-26)
I20260812 06:17:11.457458  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000006 (ops 27-31)
I20260812 06:17:11.457489  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000007 (ops 32-36)
I20260812 06:17:11.457518  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000008 (ops 37-41)
I20260812 06:17:11.457548  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000009 (ops 42-46)
I20260812 06:17:11.457578  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000010 (ops 47-51)
I20260812 06:17:11.457608  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000011 (ops 52-56)
I20260812 06:17:11.457639  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000012 (ops 57-61)
I20260812 06:17:11.457669  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000013 (ops 62-66)
I20260812 06:17:11.457700  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000014 (ops 67-71)
I20260812 06:17:11.481436  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: LogGCOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.024s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:11.481952  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:11.503657  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.022s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.504117  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling UndoDeltaBlockGCOp(cd50c96cc8b5432ba9fe00ee422521b7): 527 bytes on disk
I20260812 06:17:11.504525  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: UndoDeltaBlockGCOp(cd50c96cc8b5432ba9fe00ee422521b7) 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:11.504999  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:11.515022  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3639,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.515534  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:11.830961  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.315s	user 0.211s	sys 0.104s Metrics: {"cfile_cache_miss":1236,"cfile_cache_miss_bytes":53369142,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":6,"delta_iterators_relevant":6,"dirs.queue_time_us":1391,"lbm_read_time_us":21576,"lbm_reads_lt_1ms":1276,"lbm_write_time_us":55834,"lbm_writes_lt_1ms":1243,"peak_mem_usage":150101904,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":492,"threads_started":5,"update_count":6000}
I20260812 06:17:11.831574  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=22.032687
I20260812 06:17:11.908913  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.077s	user 0.036s	sys 0.028s Metrics: {"bytes_written":24614721,"delete_count":0,"lbm_write_time_us":27768,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:17:11.909581  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=6.157687
I20260812 06:17:11.962919  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.053s	user 0.010s	sys 0.010s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8632,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:11.963629  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=3.181125
I20260812 06:17:11.982688  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.019s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4307782,"delete_count":0,"lbm_write_time_us":4595,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:17:11.983171  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:11.997129  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":5031,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:17:11.997746  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:12.294165  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.296s	user 0.210s	sys 0.074s Metrics: {"cfile_cache_miss":1034,"cfile_cache_miss_bytes":45164086,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":906,"lbm_read_time_us":19453,"lbm_reads_lt_1ms":1074,"lbm_write_time_us":48463,"lbm_writes_lt_1ms":1043,"peak_mem_usage":125248760,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":5000}
I20260812 06:17:12.294803  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=20.048312
I20260812 06:17:12.366676  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.072s	user 0.036s	sys 0.030s Metrics: {"bytes_written":22030202,"delete_count":0,"lbm_write_time_us":33397,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":537,"reinsert_count":0,"update_count":2685}
I20260812 06:17:12.367244  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=5.165500
I20260812 06:17:12.392865  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.025s	user 0.018s	sys 0.000s Metrics: {"bytes_written":6687192,"delete_count":0,"lbm_write_time_us":7059,"lbm_writes_lt_1ms":166,"reinsert_count":0,"update_count":815}
I20260812 06:17:12.393517  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:12.598169  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.204s	user 0.164s	sys 0.040s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32856621,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":154,"lbm_read_time_us":14286,"lbm_reads_lt_1ms":764,"lbm_write_time_us":36160,"lbm_writes_lt_1ms":743,"mutex_wait_us":46,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:17:12.598764  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=18.063937
I20260812 06:17:12.649367  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.050s	user 0.035s	sys 0.016s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":21255,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:12.650104  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:12.667770  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.668311  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:12.838291  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.170s	user 0.130s	sys 0.039s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754208,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1654,"lbm_read_time_us":11913,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33126,"lbm_writes_lt_1ms":643,"mutex_wait_us":475,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:12.839020  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=14.095187
I20260812 06:17:12.890189  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.051s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19150,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.890851  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:12.906893  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5890,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.907397  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushMRSOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:12.932513  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushMRSOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.025s	user 0.023s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":354,"dirs.run_wall_time_us":1563,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1312,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:12.933295  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling LogGCOp(cd50c96cc8b5432ba9fe00ee422521b7): free 129320544 bytes of WAL
I20260812 06:17:12.933566  5983 log_reader.cc:385] T cd50c96cc8b5432ba9fe00ee422521b7: removed 13 log segments from log reader
I20260812 06:17:12.933611  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000015 (ops 72-76)
I20260812 06:17:12.933641  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000016 (ops 77-80)
I20260812 06:17:12.933660  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000017 (ops 81-85)
I20260812 06:17:12.933692  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000018 (ops 86-90)
I20260812 06:17:12.933724  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000019 (ops 91-95)
I20260812 06:17:12.933759  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000020 (ops 96-100)
I20260812 06:17:12.933792  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000021 (ops 101-105)
I20260812 06:17:12.933832  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000022 (ops 106-110)
I20260812 06:17:12.933863  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000023 (ops 111-115)
I20260812 06:17:12.933888  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000024 (ops 116-120)
I20260812 06:17:12.933919  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000025 (ops 121-124)
I20260812 06:17:12.933950  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000026 (ops 125-129)
I20260812 06:17:12.933983  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000027 (ops 130-134)
I20260812 06:17:12.957041  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: LogGCOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.024s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:12.957465  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling UndoDeltaBlockGCOp(cd50c96cc8b5432ba9fe00ee422521b7): 482 bytes on disk
I20260812 06:17:12.958103  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: UndoDeltaBlockGCOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.958665  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=5.165500
I20260812 06:17:12.978420  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.020s	user 0.010s	sys 0.008s Metrics: {"bytes_written":6400020,"delete_count":0,"lbm_write_time_us":7749,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:17:12.978932  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:12.988312  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":2907,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:17:12.988909  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling LogGCOp(cd50c96cc8b5432ba9fe00ee422521b7): free 11564893 bytes of WAL
I20260812 06:17:12.989208  5983 log_reader.cc:385] T cd50c96cc8b5432ba9fe00ee422521b7: removed 1 log segments from log reader
I20260812 06:17:12.989316  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000028 (ops 135-138)
I20260812 06:17:12.992179  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: LogGCOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:12.992563  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:13.179814  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.187s	user 0.149s	sys 0.028s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32856806,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":447,"lbm_read_time_us":12347,"lbm_reads_lt_1ms":766,"lbm_write_time_us":34801,"lbm_writes_lt_1ms":743,"mutex_wait_us":64,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:17:13.180656  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=18.063937
I20260812 06:17:13.228149  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.047s	user 0.041s	sys 0.004s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":20534,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:13.228710  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:13.241981  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.242508  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:13.406936  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.164s	user 0.104s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754211,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":414,"lbm_read_time_us":11859,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30010,"lbm_writes_lt_1ms":643,"mutex_wait_us":256,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:17:13.407632  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=14.095187
I20260812 06:17:13.454087  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.046s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":20171,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.454725  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:13.470613  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.471076  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:13.619277  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.148s	user 0.093s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651790,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1103,"lbm_read_time_us":8510,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25783,"lbm_writes_lt_1ms":543,"mutex_wait_us":306,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:13.619979  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=14.095187
I20260812 06:17:13.665558  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.045s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19760,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.666059  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:13.824586  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.158s	user 0.099s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20549263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":653,"lbm_read_time_us":10187,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23727,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":64768,"update_count":2000}
I20260812 06:17:13.825271  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=14.095187
I20260812 06:17:13.870561  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19337,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.871105  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:13.882031  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3856,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.883064  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:14.058195  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.175s	user 0.107s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":233,"lbm_read_time_us":11519,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26593,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:17:14.058851  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=14.095187
I20260812 06:17:14.103590  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.045s	user 0.021s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19486,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.104171  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:14.120429  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.016s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.121011  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:14.266599  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.145s	user 0.102s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651795,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":8557,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25236,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":52480,"update_count":2500}
I20260812 06:17:14.267246  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=14.095187
I20260812 06:17:14.320261  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.053s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22045,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.320888  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:14.333159  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4591,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.333963  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushMRSOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:14.367316  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushMRSOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":115,"dirs.run_cpu_time_us":356,"dirs.run_wall_time_us":1959,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2520,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:14.368299  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling LogGCOp(cd50c96cc8b5432ba9fe00ee422521b7): free 120553644 bytes of WAL
I20260812 06:17:14.368590  5983 log_reader.cc:385] T cd50c96cc8b5432ba9fe00ee422521b7: removed 12 log segments from log reader
I20260812 06:17:14.368660  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000029 (ops 139-143)
I20260812 06:17:14.368705  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000030 (ops 144-148)
I20260812 06:17:14.368731  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000031 (ops 149-152)
I20260812 06:17:14.368767  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000032 (ops 153-157)
I20260812 06:17:14.368796  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000033 (ops 158-162)
I20260812 06:17:14.368824  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000034 (ops 163-167)
I20260812 06:17:14.368852  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000035 (ops 168-172)
I20260812 06:17:14.368877  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000036 (ops 173-177)
I20260812 06:17:14.368906  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000037 (ops 178-182)
I20260812 06:17:14.368937  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000038 (ops 183-187)
I20260812 06:17:14.368963  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000039 (ops 188-192)
I20260812 06:17:14.368991  5983 log.cc:1079] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/cd50c96cc8b5432ba9fe00ee422521b7/wal-000000040 (ops 193-196)
I20260812 06:17:14.395364  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: LogGCOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:14.396024  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling UndoDeltaBlockGCOp(cd50c96cc8b5432ba9fe00ee422521b7): 482 bytes on disk
I20260812 06:17:14.396677  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: UndoDeltaBlockGCOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.397522  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=3.181125
I20260812 06:17:14.417557  5866 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.633s	user 1.672s	sys 0.109s
I20260812 06:17:14.426609  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.029s	user 0.012s	sys 0.012s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7324,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:14.427127  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=2.188937
I20260812 06:17:14.436043  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: FlushDeltaMemStoresOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3496,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.436578  6052 maintenance_manager.cc:419] P 71a5619ad0c24d46b66cd3a9260e260f: Scheduling MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7): perf score=1.000000
I20260812 06:17:14.520453  5866 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.102s	user 0.001s	sys 0.000s
I20260812 06:17:14.521145  5866 tablet_server.cc:179] TabletServer@127.5.186.129:0 shutting down...
I20260812 06:17:14.612521  5983 maintenance_manager.cc:643] P 71a5619ad0c24d46b66cd3a9260e260f: MajorDeltaCompactionOp(cd50c96cc8b5432ba9fe00ee422521b7) complete. Timing: real 0.176s	user 0.124s	sys 0.052s Metrics: {"cfile_cache_hit":224,"cfile_cache_hit_bytes":9071792,"cfile_cache_miss":510,"cfile_cache_miss_bytes":23785051,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":341,"lbm_read_time_us":10667,"lbm_reads_lt_1ms":542,"lbm_write_time_us":29500,"lbm_writes_lt_1ms":743,"mutex_wait_us":62,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":85376,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:17:14.613525  5866 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:14.613950  5866 tablet_replica.cc:333] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f: stopping tablet replica
I20260812 06:17:14.614202  5866 raft_consensus.cc:2243] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.614473  5866 raft_consensus.cc:2272] T cd50c96cc8b5432ba9fe00ee422521b7 P 71a5619ad0c24d46b66cd3a9260e260f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.620951  5866 tablet_server.cc:196] TabletServer@127.5.186.129:0 shutdown complete.
I20260812 06:17:14.670221  5866 master.cc:562] Master@127.5.186.190:44717 shutting down...
I20260812 06:17:14.673472  5866 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.673653  5866 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.673734  5866 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1d0fef5c6a5b42a1ac66e5774a323228: stopping tablet replica
I20260812 06:17:14.686296  5866 master.cc:584] Master@127.5.186.190:44717 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5397 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:14.765288  5866 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.186.190:37545
I20260812 06:17:14.765759  5866 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:14.767866  6102 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:14.767982  6100 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:14.767918  5866 server_base.cc:1061] running on GCE node
W20260812 06:17:14.767889  6098 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:14.768296  5866 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:14.768342  5866 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:14.768402  5866 hybrid_clock.cc:648] HybridClock initialized: now 1786515434768401 us; error 0 us; skew 500 ppm
I20260812 06:17:14.769963  5866 webserver.cc:533] Webserver started at http://127.5.186.190:41001/ using document root <none> and password file <none>
I20260812 06:17:14.770128  5866 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:14.770174  5866 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:14.770251  5866 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:14.770640  5866 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/master-0-root/instance:
uuid: "4a087cf7978d4c51afd261b7fbd0cbb6"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-vq2q"
I20260812 06:17:14.772116  5866 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:14.773031  6108 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:14.773304  5866 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:14.773380  5866 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/master-0-root
uuid: "4a087cf7978d4c51afd261b7fbd0cbb6"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-vq2q"
I20260812 06:17:14.773443  5866 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-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:14.778084  5866 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:14.778421  5866 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:14.782387  5866 rpc_server.cc:307] RPC server started. Bound to: 127.5.186.190:37545
I20260812 06:17:14.784051  6168 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.186.190:37545 every 8 connection(s)
I20260812 06:17:14.784495  6169 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:14.786401  6169 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6: Bootstrap starting.
I20260812 06:17:14.787200  6169 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:14.788167  6169 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6: No bootstrap required, opened a new log
I20260812 06:17:14.788550  6169 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4a087cf7978d4c51afd261b7fbd0cbb6" member_type: VOTER }
I20260812 06:17:14.788640  6169 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:14.788671  6169 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4a087cf7978d4c51afd261b7fbd0cbb6, State: Initialized, Role: FOLLOWER
I20260812 06:17:14.788810  6169 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [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: "4a087cf7978d4c51afd261b7fbd0cbb6" member_type: VOTER }
I20260812 06:17:14.788888  6169 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:14.788929  6169 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:14.788978  6169 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:14.789669  6169 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4a087cf7978d4c51afd261b7fbd0cbb6" member_type: VOTER }
I20260812 06:17:14.789800  6169 leader_election.cc:304] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [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: 4a087cf7978d4c51afd261b7fbd0cbb6; no voters: 
I20260812 06:17:14.789973  6169 leader_election.cc:290] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:14.790071  6173 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:14.790254  6173 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 1 LEADER]: Becoming Leader. State: Replica: 4a087cf7978d4c51afd261b7fbd0cbb6, State: Running, Role: LEADER
I20260812 06:17:14.790490  6169 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:14.790470  6173 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [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: "4a087cf7978d4c51afd261b7fbd0cbb6" member_type: VOTER }
I20260812 06:17:14.790987  6174 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4a087cf7978d4c51afd261b7fbd0cbb6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4a087cf7978d4c51afd261b7fbd0cbb6" member_type: VOTER } }
I20260812 06:17:14.791016  6175 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4a087cf7978d4c51afd261b7fbd0cbb6. Latest consensus state: current_term: 1 leader_uuid: "4a087cf7978d4c51afd261b7fbd0cbb6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4a087cf7978d4c51afd261b7fbd0cbb6" member_type: VOTER } }
I20260812 06:17:14.791082  6174 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:14.791109  6175 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:14.791327  6178 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:14.792230  6178 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:14.792448  5866 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:14.794154  6178 catalog_manager.cc:1383] Generated new cluster ID: b65edfe5d36d4ba2a1ef943f01e69cd3
I20260812 06:17:14.794199  6178 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:14.827627  6178 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:14.828197  6178 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:14.839126  6178 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6: Generated new TSK 0
I20260812 06:17:14.839310  6178 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:14.857350  5866 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:14.859283  6194 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:14.859297  6196 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:14.859295  6198 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:14.859617  5866 server_base.cc:1061] running on GCE node
I20260812 06:17:14.859786  5866 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:14.859822  5866 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:14.859838  5866 hybrid_clock.cc:648] HybridClock initialized: now 1786515434859837 us; error 0 us; skew 500 ppm
I20260812 06:17:14.860601  5866 webserver.cc:533] Webserver started at http://127.5.186.129:45811/ using document root <none> and password file <none>
I20260812 06:17:14.860743  5866 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:14.860782  5866 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:14.860838  5866 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:14.861243  5866 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/instance:
uuid: "6c9c650325734c1c9a22bb46a370b5d5"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-vq2q"
I20260812 06:17:14.862682  5866 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:14.863615  6204 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:14.863827  5866 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:14.863898  5866 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root
uuid: "6c9c650325734c1c9a22bb46a370b5d5"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-vq2q"
I20260812 06:17:14.863953  5866 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-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:14.884266  5866 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:14.884630  5866 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:14.884915  5866 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:14.885421  5866 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:14.885459  5866 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.885496  5866 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:14.885524  5866 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.889691  5866 rpc_server.cc:307] RPC server started. Bound to: 127.5.186.129:36909
I20260812 06:17:14.891968  6278 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.186.129:36909 every 8 connection(s)
I20260812 06:17:14.900816  6279 heartbeater.cc:344] Connected to a master server at 127.5.186.190:37545
I20260812 06:17:14.900923  6279 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:14.901137  6279 heartbeater.cc:507] Master 127.5.186.190:37545 requested a full tablet report, sending...
I20260812 06:17:14.901811  6129 ts_manager.cc:194] Registered new tserver with Master: 6c9c650325734c1c9a22bb46a370b5d5 (127.5.186.129:36909)
I20260812 06:17:14.902410  5866 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012034294s
I20260812 06:17:14.902561  6129 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53706
I20260812 06:17:14.909335  6129 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53708:
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:14.918084  6239 tablet_service.cc:1511] Processing CreateTablet for tablet 29b31af285a248ee88229019e5950141 (DEFAULT_TABLE table=heavy-update-compaction-test [id=51b4de9ebe2a4fa497497d6fa55779de]), partition=
I20260812 06:17:14.918339  6239 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 29b31af285a248ee88229019e5950141. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:14.920504  6296 tablet_bootstrap.cc:492] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Bootstrap starting.
I20260812 06:17:14.921413  6296 tablet_bootstrap.cc:654] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:14.922427  6296 tablet_bootstrap.cc:492] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: No bootstrap required, opened a new log
I20260812 06:17:14.922505  6296 ts_tablet_manager.cc:1403] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:14.922930  6296 raft_consensus.cc:359] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c9c650325734c1c9a22bb46a370b5d5" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36909 } }
I20260812 06:17:14.923046  6296 raft_consensus.cc:385] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:14.923087  6296 raft_consensus.cc:740] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6c9c650325734c1c9a22bb46a370b5d5, State: Initialized, Role: FOLLOWER
I20260812 06:17:14.923224  6296 consensus_queue.cc:260] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [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: "6c9c650325734c1c9a22bb46a370b5d5" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36909 } }
I20260812 06:17:14.923306  6296 raft_consensus.cc:399] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:14.923357  6296 raft_consensus.cc:493] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:14.923408  6296 raft_consensus.cc:3060] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:14.924139  6296 raft_consensus.cc:515] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c9c650325734c1c9a22bb46a370b5d5" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36909 } }
I20260812 06:17:14.924266  6296 leader_election.cc:304] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [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: 6c9c650325734c1c9a22bb46a370b5d5; no voters: 
I20260812 06:17:14.924427  6296 leader_election.cc:290] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:14.924538  6298 raft_consensus.cc:2804] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:14.924726  6296 ts_tablet_manager.cc:1434] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:14.924769  6279 heartbeater.cc:499] Master 127.5.186.190:37545 was elected leader, sending a full tablet report...
I20260812 06:17:14.924741  6298 raft_consensus.cc:697] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 1 LEADER]: Becoming Leader. State: Replica: 6c9c650325734c1c9a22bb46a370b5d5, State: Running, Role: LEADER
I20260812 06:17:14.924955  6298 consensus_queue.cc:237] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [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: "6c9c650325734c1c9a22bb46a370b5d5" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36909 } }
I20260812 06:17:14.926302  6129 catalog_manager.cc:5719] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6c9c650325734c1c9a22bb46a370b5d5 (127.5.186.129). New cstate: current_term: 1 leader_uuid: "6c9c650325734c1c9a22bb46a370b5d5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c9c650325734c1c9a22bb46a370b5d5" member_type: VOTER last_known_addr { host: "127.5.186.129" port: 36909 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:14.985633  5866 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.014s	sys 0.008s
I20260812 06:17:15.142534  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushMRSOp(29b31af285a248ee88229019e5950141): perf score=21.039315
I20260812 06:17:15.305472  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushMRSOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.163s	user 0.127s	sys 0.032s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":783,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39407,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:17:15.306161  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling LogGCOp(29b31af285a248ee88229019e5950141): free 20743880 bytes of WAL
I20260812 06:17:15.306396  6210 log_reader.cc:385] T 29b31af285a248ee88229019e5950141: removed 2 log segments from log reader
I20260812 06:17:15.306440  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000001 (ops 1-6)
I20260812 06:17:15.306471  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000002 (ops 7-11)
I20260812 06:17:15.309888  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: LogGCOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:15.310209  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:15.320712  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.321326  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:15.465463  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.144s	user 0.094s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":676,"lbm_read_time_us":10310,"lbm_reads_lt_1ms":468,"lbm_write_time_us":21991,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":317,"threads_started":5,"update_count":2000}
I20260812 06:17:15.466048  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=10.126437
I20260812 06:17:15.508553  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.042s	user 0.025s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17359,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.509153  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling UndoDeltaBlockGCOp(29b31af285a248ee88229019e5950141): 20513815 bytes on disk
I20260812 06:17:15.509641  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: UndoDeltaBlockGCOp(29b31af285a248ee88229019e5950141) 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:15.510110  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:15.526227  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.526757  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:15.645746  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.119s	user 0.102s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1222,"lbm_read_time_us":10240,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20896,"lbm_writes_lt_1ms":443,"mutex_wait_us":99,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:17:15.646306  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=10.126437
I20260812 06:17:15.680706  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.034s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13790,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.681253  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:15.692059  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.692719  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:15.825881  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.133s	user 0.113s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":672,"lbm_read_time_us":10190,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22708,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28416,"update_count":2000}
I20260812 06:17:15.826412  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=10.126437
I20260812 06:17:15.860788  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.034s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13041,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.861336  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:15.872479  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4070,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.873167  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:15.989972  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.117s	user 0.096s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":606,"lbm_read_time_us":9827,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19750,"lbm_writes_lt_1ms":443,"mutex_wait_us":245,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:17:15.990532  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=10.126437
I20260812 06:17:16.040462  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.050s	user 0.032s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16389,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.040970  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:16.051453  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.051918  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:16.192381  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.140s	user 0.099s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":10229,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21159,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:17:16.192986  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=10.126437
I20260812 06:17:16.237313  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.044s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14048,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.237831  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:16.248374  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.249076  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:16.372769  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.123s	user 0.102s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":613,"lbm_read_time_us":8637,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22475,"lbm_writes_lt_1ms":443,"mutex_wait_us":276,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":38528,"update_count":2000}
I20260812 06:17:16.373438  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=10.126437
I20260812 06:17:16.419028  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.045s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13466,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.419734  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:16.435426  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.435890  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushMRSOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:16.469436  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushMRSOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.033s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1256,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1327,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:16.470324  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling LogGCOp(29b31af285a248ee88229019e5950141): free 120553372 bytes of WAL
I20260812 06:17:16.470571  6210 log_reader.cc:385] T 29b31af285a248ee88229019e5950141: removed 12 log segments from log reader
I20260812 06:17:16.470638  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000003 (ops 12-16)
I20260812 06:17:16.470698  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000004 (ops 17-21)
I20260812 06:17:16.470745  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000005 (ops 22-26)
I20260812 06:17:16.470811  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000006 (ops 27-31)
I20260812 06:17:16.470857  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000007 (ops 32-36)
I20260812 06:17:16.470899  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000008 (ops 37-40)
I20260812 06:17:16.470939  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000009 (ops 41-45)
I20260812 06:17:16.470983  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000010 (ops 46-50)
I20260812 06:17:16.471031  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000011 (ops 51-55)
I20260812 06:17:16.471076  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000012 (ops 56-60)
I20260812 06:17:16.471117  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000013 (ops 61-64)
I20260812 06:17:16.471158  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000014 (ops 65-69)
I20260812 06:17:16.494592  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: LogGCOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:16.495021  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling UndoDeltaBlockGCOp(29b31af285a248ee88229019e5950141): 447 bytes on disk
I20260812 06:17:16.495556  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: UndoDeltaBlockGCOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.496069  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=3.181125
I20260812 06:17:16.512967  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":5087239,"delete_count":0,"lbm_write_time_us":6526,"lbm_writes_lt_1ms":127,"reinsert_count":0,"update_count":620}
I20260812 06:17:16.513418  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=1.196750
I20260812 06:17:16.522563  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.009s	user 0.005s	sys 0.002s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":2806,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:16.523085  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:16.688208  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.165s	user 0.139s	sys 0.023s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":834,"lbm_read_time_us":13234,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29916,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9728,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:17:16.688756  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=14.095187
I20260812 06:17:16.742424  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.053s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409886,"delete_count":0,"lbm_write_time_us":22581,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.743345  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:16.757545  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4003,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.758078  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:16.911878  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.154s	user 0.106s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815668,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":8784,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27583,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:17:16.912529  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=14.095187
I20260812 06:17:16.974570  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.062s	user 0.018s	sys 0.028s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23309,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.975150  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:16.986131  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.986640  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:17.145144  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.158s	user 0.134s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":152,"lbm_read_time_us":11522,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27652,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:17.145710  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=11.118625
I20260812 06:17:17.185293  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.039s	user 0.016s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13653,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:17.185889  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:17.208643  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.023s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4430,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.209293  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:17.224577  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.225160  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:17.392237  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.167s	user 0.124s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":244,"lbm_read_time_us":11193,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27417,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:17:17.392771  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=14.095187
I20260812 06:17:17.458259  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.065s	user 0.029s	sys 0.035s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":27291,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.458953  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:17.469417  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3780,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.469991  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:17.653216  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.183s	user 0.128s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":768,"lbm_read_time_us":13236,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28768,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:17.653852  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=14.095187
I20260812 06:17:17.742498  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.088s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":55069,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.743165  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:17.754846  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4417,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.755306  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushMRSOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:17.783703  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushMRSOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":214,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1515,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1747,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":896}
I20260812 06:17:17.784389  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling LogGCOp(29b31af285a248ee88229019e5950141): free 112239273 bytes of WAL
I20260812 06:17:17.784654  6210 log_reader.cc:385] T 29b31af285a248ee88229019e5950141: removed 11 log segments from log reader
I20260812 06:17:17.784711  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000015 (ops 70-74)
I20260812 06:17:17.784752  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000016 (ops 75-79)
I20260812 06:17:17.784778  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000017 (ops 80-84)
I20260812 06:17:17.784850  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000018 (ops 85-89)
I20260812 06:17:17.784881  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000019 (ops 90-94)
I20260812 06:17:17.784914  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000020 (ops 95-99)
I20260812 06:17:17.784945  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000021 (ops 100-104)
I20260812 06:17:17.784974  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000022 (ops 105-109)
I20260812 06:17:17.785004  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000023 (ops 110-114)
I20260812 06:17:17.785034  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000024 (ops 115-118)
I20260812 06:17:17.785064  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000025 (ops 119-123)
I20260812 06:17:17.803064  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: LogGCOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.018s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:17:17.803464  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling UndoDeltaBlockGCOp(29b31af285a248ee88229019e5950141): 447 bytes on disk
I20260812 06:17:17.803977  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: UndoDeltaBlockGCOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.804519  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:17.823143  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.018s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.823577  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:17.838104  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.838636  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:18.063406  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.225s	user 0.166s	sys 0.056s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2616,"lbm_read_time_us":13896,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37167,"lbm_writes_lt_1ms":743,"mutex_wait_us":2028,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:17:18.064141  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=17.071750
I20260812 06:17:18.127912  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.064s	user 0.025s	sys 0.036s Metrics: {"bytes_written":19568756,"delete_count":0,"lbm_write_time_us":30077,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":479,"reinsert_count":0,"update_count":2385}
I20260812 06:17:18.128456  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=3.181125
I20260812 06:17:18.142249  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":5046221,"delete_count":0,"lbm_write_time_us":5262,"lbm_writes_lt_1ms":126,"reinsert_count":0,"update_count":615}
I20260812 06:17:18.142752  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:18.349880  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.207s	user 0.147s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":175,"lbm_read_time_us":14529,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34335,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:18.350451  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=16.079562
I20260812 06:17:18.405463  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.055s	user 0.040s	sys 0.012s Metrics: {"bytes_written":18132914,"delete_count":0,"lbm_write_time_us":23465,"lbm_writes_lt_1ms":445,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2210}
I20260812 06:17:18.405978  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=1.196750
I20260812 06:17:18.416402  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.010s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2789859,"delete_count":0,"lbm_write_time_us":2777,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:17:18.416839  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:18.426489  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3511,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.426965  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:18.796396  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.369s	user 0.257s	sys 0.111s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918173,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1095,"lbm_read_time_us":29414,"lbm_reads_lt_1ms":673,"lbm_write_time_us":66626,"lbm_writes_lt_1ms":643,"mutex_wait_us":540,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:18.797952  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=14.095187
I20260812 06:17:18.869383  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.071s	user 0.040s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27901,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.870370  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:18.884907  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.885476  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:19.294351  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.409s	user 0.280s	sys 0.129s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":255,"lbm_read_time_us":75225,"lbm_reads_1-10_ms":3,"lbm_reads_lt_1ms":569,"lbm_write_time_us":36658,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:17:19.295080  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=14.095187
I20260812 06:17:19.343941  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.049s	user 0.013s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16199,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.344547  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:19.359988  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.360651  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:19.529597  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.169s	user 0.128s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1383,"lbm_read_time_us":12740,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24906,"lbm_writes_lt_1ms":543,"mutex_wait_us":658,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:17:19.530143  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=14.095187
I20260812 06:17:19.582630  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.052s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16300,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.583271  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:19.598958  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.599526  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushMRSOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:19.639456  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushMRSOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.040s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1510,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1488,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:19.640226  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling LogGCOp(29b31af285a248ee88229019e5950141): free 112239596 bytes of WAL
I20260812 06:17:19.640455  6210 log_reader.cc:385] T 29b31af285a248ee88229019e5950141: removed 11 log segments from log reader
I20260812 06:17:19.640499  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000026 (ops 124-128)
I20260812 06:17:19.640529  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000027 (ops 129-133)
I20260812 06:17:19.640559  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000028 (ops 134-138)
I20260812 06:17:19.640591  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000029 (ops 139-142)
I20260812 06:17:19.640616  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000030 (ops 143-147)
I20260812 06:17:19.640647  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000031 (ops 148-152)
I20260812 06:17:19.640679  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000032 (ops 153-157)
I20260812 06:17:19.640709  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000033 (ops 158-162)
I20260812 06:17:19.640740  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000034 (ops 163-167)
I20260812 06:17:19.640771  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000035 (ops 168-172)
I20260812 06:17:19.640802  6210 log.cc:1079] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: Deleting log segment in path: /tmp/dist-test-taskxyqkB9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429346629-5866-0/minicluster-data/ts-0-root/wals/29b31af285a248ee88229019e5950141/wal-000000036 (ops 173-177)
I20260812 06:17:19.659976  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: LogGCOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.020s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:17:19.660477  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=3.181125
I20260812 06:17:19.683694  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.023s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4389831,"delete_count":0,"lbm_write_time_us":4492,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:17:19.684237  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling UndoDeltaBlockGCOp(29b31af285a248ee88229019e5950141): 448 bytes on disk
I20260812 06:17:19.684726  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: UndoDeltaBlockGCOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.685376  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:19.700606  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5144,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:17:19.701462  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:19.930120  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.228s	user 0.150s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":651,"lbm_read_time_us":16395,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37667,"lbm_writes_lt_1ms":743,"mutex_wait_us":248,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:17:19.930725  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=18.063937
I20260812 06:17:19.983176  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.052s	user 0.046s	sys 0.003s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":22792,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.983770  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=2.188937
I20260812 06:17:19.999207  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.999684  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141): perf score=1.000000
I20260812 06:17:20.116098  5866 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.130s	user 1.852s	sys 0.121s
I20260812 06:17:20.154042  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: MajorDeltaCompactionOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.154s	user 0.117s	sys 0.036s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":10445,"lbm_reads_lt_1ms":668,"lbm_write_time_us":33488,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:17:20.154561  6281 maintenance_manager.cc:419] P 6c9c650325734c1c9a22bb46a370b5d5: Scheduling FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141): perf score=10.126437
I20260812 06:17:20.172515  5866 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.056s	user 0.001s	sys 0.000s
I20260812 06:17:20.173012  5866 tablet_server.cc:179] TabletServer@127.5.186.129:0 shutting down...
I20260812 06:17:20.185397  6210 maintenance_manager.cc:643] P 6c9c650325734c1c9a22bb46a370b5d5: FlushDeltaMemStoresOp(29b31af285a248ee88229019e5950141) complete. Timing: real 0.031s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13031,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.185937  5866 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:20.186156  5866 tablet_replica.cc:333] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5: stopping tablet replica
I20260812 06:17:20.186291  5866 raft_consensus.cc:2243] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.186450  5866 raft_consensus.cc:2272] T 29b31af285a248ee88229019e5950141 P 6c9c650325734c1c9a22bb46a370b5d5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.199855  5866 tablet_server.cc:196] TabletServer@127.5.186.129:0 shutdown complete.
I20260812 06:17:20.213220  5866 master.cc:562] Master@127.5.186.190:37545 shutting down...
I20260812 06:17:20.216161  5866 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.216328  5866 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.216403  5866 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4a087cf7978d4c51afd261b7fbd0cbb6: stopping tablet replica
I20260812 06:17:20.228655  5866 master.cc:584] Master@127.5.186.190:37545 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5547 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10945 ms total)

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