[==========] 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.418581 12763 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.118.254:41791
I20260812 06:17:09.419700 12763 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.420344 12763 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.427299 12769 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.427384 12773 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.427523 12763 server_base.cc:1061] running on GCE node
W20260812 06:17:09.427767 12770 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:09.428287 12763 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.428421 12763 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.428515 12763 hybrid_clock.cc:648] HybridClock initialized: now 1786515429428513 us; error 0 us; skew 500 ppm
I20260812 06:17:09.430554 12763 webserver.cc:533] Webserver started at http://127.12.118.254:33071/ using document root <none> and password file <none>
I20260812 06:17:09.431151 12763 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.431242 12763 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.431576 12763 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.433260 12763 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/master-0-root/instance:
uuid: "79a4cd0e2a024732ba8651928f314bc7"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-c12x"
I20260812 06:17:09.437521 12763 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:17:09.440176 12782 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.441326 12763 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:09.441504 12763 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/master-0-root
uuid: "79a4cd0e2a024732ba8651928f314bc7"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-c12x"
I20260812 06:17:09.441629 12763 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-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.452602 12763 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.453233 12763 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.453413 12763 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.461606 12763 rpc_server.cc:307] RPC server started. Bound to: 127.12.118.254:41791
I20260812 06:17:09.461671 12858 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.118.254:41791 every 8 connection(s)
I20260812 06:17:09.464123 12859 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.470031 12859 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7: Bootstrap starting.
I20260812 06:17:09.472548 12859 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.473491 12859 log.cc:826] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:09.475601 12859 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7: No bootstrap required, opened a new log
I20260812 06:17:09.478824 12859 raft_consensus.cc:359] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79a4cd0e2a024732ba8651928f314bc7" member_type: VOTER }
I20260812 06:17:09.479038 12859 raft_consensus.cc:385] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.479153 12859 raft_consensus.cc:740] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 79a4cd0e2a024732ba8651928f314bc7, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.480273 12859 consensus_queue.cc:260] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [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: "79a4cd0e2a024732ba8651928f314bc7" member_type: VOTER }
I20260812 06:17:09.480436 12859 raft_consensus.cc:399] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.480599 12859 raft_consensus.cc:493] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.480736 12859 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.481601 12859 raft_consensus.cc:515] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79a4cd0e2a024732ba8651928f314bc7" member_type: VOTER }
I20260812 06:17:09.482067 12859 leader_election.cc:304] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [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: 79a4cd0e2a024732ba8651928f314bc7; no voters: 
I20260812 06:17:09.482404 12859 leader_election.cc:290] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.482741 12867 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.483023 12867 raft_consensus.cc:697] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 1 LEADER]: Becoming Leader. State: Replica: 79a4cd0e2a024732ba8651928f314bc7, State: Running, Role: LEADER
I20260812 06:17:09.483516 12867 consensus_queue.cc:237] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [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: "79a4cd0e2a024732ba8651928f314bc7" member_type: VOTER }
I20260812 06:17:09.483855 12859 sys_catalog.cc:565] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:09.485680 12869 sys_catalog.cc:455] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 79a4cd0e2a024732ba8651928f314bc7. Latest consensus state: current_term: 1 leader_uuid: "79a4cd0e2a024732ba8651928f314bc7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79a4cd0e2a024732ba8651928f314bc7" member_type: VOTER } }
I20260812 06:17:09.485743 12868 sys_catalog.cc:455] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "79a4cd0e2a024732ba8651928f314bc7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79a4cd0e2a024732ba8651928f314bc7" member_type: VOTER } }
I20260812 06:17:09.485823 12869 sys_catalog.cc:458] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.485843 12868 sys_catalog.cc:458] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.486702 12763 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:09.488994 12887 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:09.489089 12887 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:09.489216 12882 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:09.490048 12882 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:09.495464 12882 catalog_manager.cc:1383] Generated new cluster ID: 508b578ce39a4b829dcd2cd9f364a070
I20260812 06:17:09.495544 12882 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:09.513074 12882 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:09.514034 12882 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:09.520170 12882 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7: Generated new TSK 0
I20260812 06:17:09.520805 12882 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:09.552224 12763 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.555050 12903 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:09.555124 12900 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.555315 12901 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:09.555401 12763 server_base.cc:1061] running on GCE node
I20260812 06:17:09.555730 12763 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.555791 12763 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.555815 12763 hybrid_clock.cc:648] HybridClock initialized: now 1786515429555815 us; error 0 us; skew 500 ppm
I20260812 06:17:09.556787 12763 webserver.cc:533] Webserver started at http://127.12.118.193:40103/ using document root <none> and password file <none>
I20260812 06:17:09.556968 12763 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.557034 12763 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.557114 12763 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.557583 12763 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/instance:
uuid: "5c6841b0845044eb801dd8606ea1bc1d"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-c12x"
I20260812 06:17:09.559725 12763 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:09.560983 12909 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.561301 12763 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:09.561368 12763 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root
uuid: "5c6841b0845044eb801dd8606ea1bc1d"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-c12x"
I20260812 06:17:09.561512 12763 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-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.584728 12763 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.585372 12763 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.585975 12763 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:09.587006 12763 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:09.587071 12763 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.587149 12763 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:09.587193 12763 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.595156 12763 rpc_server.cc:307] RPC server started. Bound to: 127.12.118.193:39535
I20260812 06:17:09.595196 13011 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.118.193:39535 every 8 connection(s)
I20260812 06:17:09.607085 13012 heartbeater.cc:344] Connected to a master server at 127.12.118.254:41791
I20260812 06:17:09.607398 13012 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:09.607941 13012 heartbeater.cc:507] Master 127.12.118.254:41791 requested a full tablet report, sending...
I20260812 06:17:09.609539 12807 ts_manager.cc:194] Registered new tserver with Master: 5c6841b0845044eb801dd8606ea1bc1d (127.12.118.193:39535)
I20260812 06:17:09.609635 12763 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013594489s
I20260812 06:17:09.611367 12807 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41056
I20260812 06:17:09.623916 12807 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41060:
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.640986 12956 tablet_service.cc:1511] Processing CreateTablet for tablet a8fb03bf50f341c999801f46ca9d969f (DEFAULT_TABLE table=heavy-update-compaction-test [id=201e20a04d2f47dcbe0109343871c9f0]), partition=
I20260812 06:17:09.641778 12956 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a8fb03bf50f341c999801f46ca9d969f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:09.644690 13031 tablet_bootstrap.cc:492] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Bootstrap starting.
I20260812 06:17:09.645962 13031 tablet_bootstrap.cc:654] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.647687 13031 tablet_bootstrap.cc:492] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: No bootstrap required, opened a new log
I20260812 06:17:09.647819 13031 ts_tablet_manager.cc:1403] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:09.648342 13031 raft_consensus.cc:359] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c6841b0845044eb801dd8606ea1bc1d" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 39535 } }
I20260812 06:17:09.648489 13031 raft_consensus.cc:385] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.648543 13031 raft_consensus.cc:740] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5c6841b0845044eb801dd8606ea1bc1d, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.648697 13031 consensus_queue.cc:260] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [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: "5c6841b0845044eb801dd8606ea1bc1d" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 39535 } }
I20260812 06:17:09.648818 13031 raft_consensus.cc:399] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.648872 13031 raft_consensus.cc:493] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.648932 13031 raft_consensus.cc:3060] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.649740 13031 raft_consensus.cc:515] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c6841b0845044eb801dd8606ea1bc1d" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 39535 } }
I20260812 06:17:09.649916 13031 leader_election.cc:304] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [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: 5c6841b0845044eb801dd8606ea1bc1d; no voters: 
I20260812 06:17:09.650194 13031 leader_election.cc:290] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.650300 13035 raft_consensus.cc:2804] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.650527 13035 raft_consensus.cc:697] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 1 LEADER]: Becoming Leader. State: Replica: 5c6841b0845044eb801dd8606ea1bc1d, State: Running, Role: LEADER
I20260812 06:17:09.650604 13031 ts_tablet_manager.cc:1434] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:09.651031 13035 consensus_queue.cc:237] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [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: "5c6841b0845044eb801dd8606ea1bc1d" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 39535 } }
I20260812 06:17:09.651127 13012 heartbeater.cc:499] Master 127.12.118.254:41791 was elected leader, sending a full tablet report...
I20260812 06:17:09.654529 12807 catalog_manager.cc:5719] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d reported cstate change: term changed from 0 to 1, leader changed from <none> to 5c6841b0845044eb801dd8606ea1bc1d (127.12.118.193). New cstate: current_term: 1 leader_uuid: "5c6841b0845044eb801dd8606ea1bc1d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c6841b0845044eb801dd8606ea1bc1d" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 39535 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:09.739248 12763 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.075s	user 0.028s	sys 0.005s
I20260812 06:17:09.846714 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushMRSOp(a8fb03bf50f341c999801f46ca9d969f): perf score=10.125253
I20260812 06:17:10.005208 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushMRSOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.158s	user 0.126s	sys 0.020s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":700,"delete_count":0,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":289,"dirs.run_wall_time_us":1208,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33452,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":168,"threads_started":1,"update_count":1000}
I20260812 06:17:10.006899 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling LogGCOp(a8fb03bf50f341c999801f46ca9d969f): free 8725963 bytes of WAL
I20260812 06:17:10.007303 12917 log_reader.cc:385] T a8fb03bf50f341c999801f46ca9d969f: removed 1 log segments from log reader
I20260812 06:17:10.007576 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000001 (ops 1-6)
I20260812 06:17:10.009747 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: LogGCOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:10.010300 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:10.029843 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.019s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6364,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.030376 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:10.155330 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.125s	user 0.089s	sys 0.032s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487935,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":7788,"lbm_reads_lt_1ms":364,"lbm_write_time_us":23017,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":316,"threads_started":5,"update_count":1500}
I20260812 06:17:10.155982 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=10.126437
I20260812 06:17:10.205286 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.049s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15577,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.205763 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling UndoDeltaBlockGCOp(a8fb03bf50f341c999801f46ca9d969f): 12308947 bytes on disk
I20260812 06:17:10.206259 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: UndoDeltaBlockGCOp(a8fb03bf50f341c999801f46ca9d969f) 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:10.206661 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:10.219420 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.220157 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:10.363847 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.144s	user 0.096s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":996,"lbm_read_time_us":10774,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24298,"lbm_writes_lt_1ms":443,"mutex_wait_us":271,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:17:10.364404 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=10.126437
I20260812 06:17:10.432631 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.068s	user 0.036s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22417,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.433282 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:10.446679 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.447784 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:10.608237 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.160s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":553,"lbm_read_time_us":13928,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25674,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:17:10.608929 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=10.126437
I20260812 06:17:10.656267 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.047s	user 0.036s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17614,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.656847 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:10.670495 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.670996 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:10.808560 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.137s	user 0.105s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":10200,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28653,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2000}
I20260812 06:17:10.809322 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=10.126437
I20260812 06:17:10.859109 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.050s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18040,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.859829 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:10.874851 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.875855 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:11.010691 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.135s	user 0.101s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":633,"lbm_read_time_us":10892,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24089,"lbm_writes_lt_1ms":443,"mutex_wait_us":104,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2000}
I20260812 06:17:11.011507 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=10.126437
I20260812 06:17:11.058291 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.047s	user 0.020s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15065,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.058993 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:11.077927 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.078680 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:11.229579 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.151s	user 0.107s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":946,"lbm_read_time_us":10824,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23648,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:17:11.230239 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=10.126437
I20260812 06:17:11.278179 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.048s	user 0.017s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19553,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.278724 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:11.290360 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.291245 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushMRSOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:11.325124 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushMRSOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.034s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":332,"dirs.run_wall_time_us":1305,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1388,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:11.326030 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling LogGCOp(a8fb03bf50f341c999801f46ca9d969f): free 112239308 bytes of WAL
I20260812 06:17:11.326283 12917 log_reader.cc:385] T a8fb03bf50f341c999801f46ca9d969f: removed 11 log segments from log reader
I20260812 06:17:11.326328 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000002 (ops 7-11)
I20260812 06:17:11.326357 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000003 (ops 12-16)
I20260812 06:17:11.326411 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000004 (ops 17-21)
I20260812 06:17:11.326457 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000005 (ops 22-26)
I20260812 06:17:11.326524 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000006 (ops 27-31)
I20260812 06:17:11.326586 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000007 (ops 32-36)
I20260812 06:17:11.326627 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000008 (ops 37-40)
I20260812 06:17:11.326668 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000009 (ops 41-45)
I20260812 06:17:11.326702 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000010 (ops 46-50)
I20260812 06:17:11.326745 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000011 (ops 51-55)
I20260812 06:17:11.326782 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000012 (ops 56-60)
I20260812 06:17:11.353835 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: LogGCOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.028s	user 0.003s	sys 0.022s Metrics: {}
I20260812 06:17:11.354417 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling UndoDeltaBlockGCOp(a8fb03bf50f341c999801f46ca9d969f): 447 bytes on disk
I20260812 06:17:11.355031 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: UndoDeltaBlockGCOp(a8fb03bf50f341c999801f46ca9d969f) 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:11.355603 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:11.369220 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4225734,"delete_count":0,"lbm_write_time_us":5045,"lbm_writes_lt_1ms":106,"mutex_wait_us":182,"reinsert_count":0,"update_count":515}
I20260812 06:17:11.369658 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling LogGCOp(a8fb03bf50f341c999801f46ca9d969f): free 11564875 bytes of WAL
I20260812 06:17:11.369854 12917 log_reader.cc:385] T a8fb03bf50f341c999801f46ca9d969f: removed 1 log segments from log reader
I20260812 06:17:11.369896 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000013 (ops 61-64)
I20260812 06:17:11.372175 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: LogGCOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:11.372592 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:11.392072 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":3979583,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:11.395386 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:11.599890 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.204s	user 0.119s	sys 0.085s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795408,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1424,"lbm_read_time_us":13557,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35683,"lbm_writes_lt_1ms":643,"mutex_wait_us":575,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:17:11.600383 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=14.095187
I20260812 06:17:11.666448 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.066s	user 0.023s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26896,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.667053 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:11.687741 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.020s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.688269 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:11.887580 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.199s	user 0.119s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":857,"lbm_read_time_us":14720,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32264,"lbm_writes_lt_1ms":543,"mutex_wait_us":90,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:17:11.888830 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=14.095187
I20260812 06:17:11.948372 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.059s	user 0.048s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24619,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.948904 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:11.963164 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4689,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.963686 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:12.157317 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.193s	user 0.134s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":881,"lbm_read_time_us":12739,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29513,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:17:12.158003 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=14.095187
I20260812 06:17:12.206100 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.048s	user 0.020s	sys 0.023s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":20915,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.206585 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:12.219352 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4552,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.220011 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:12.377895 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.158s	user 0.109s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692754,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":832,"lbm_read_time_us":10188,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28441,"lbm_writes_lt_1ms":543,"mutex_wait_us":258,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:17:12.378648 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=14.095187
I20260812 06:17:12.432286 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.053s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22002,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.433132 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:12.445439 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4649,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.445905 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:12.597247 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.151s	user 0.116s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692761,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":384,"lbm_read_time_us":10589,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30516,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:12.598263 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=10.126437
I20260812 06:17:12.639676 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.041s	user 0.013s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18690,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.640242 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:12.653991 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.654523 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:12.789901 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.135s	user 0.115s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":11528,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25781,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:17:12.790521 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=10.126437
I20260812 06:17:12.842418 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.052s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18769,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.842931 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:12.853863 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4269,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.854368 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushMRSOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:12.884765 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushMRSOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":173,"dirs.run_wall_time_us":1120,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1893,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:12.885514 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling LogGCOp(a8fb03bf50f341c999801f46ca9d969f): free 121006442 bytes of WAL
I20260812 06:17:12.885716 12917 log_reader.cc:385] T a8fb03bf50f341c999801f46ca9d969f: removed 12 log segments from log reader
I20260812 06:17:12.885773 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000014 (ops 65-69)
I20260812 06:17:12.885824 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000015 (ops 70-74)
I20260812 06:17:12.885881 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000016 (ops 75-78)
I20260812 06:17:12.885926 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000017 (ops 79-83)
I20260812 06:17:12.885960 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000018 (ops 84-88)
I20260812 06:17:12.886025 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000019 (ops 89-93)
I20260812 06:17:12.886067 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000020 (ops 94-98)
I20260812 06:17:12.886108 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000021 (ops 99-103)
I20260812 06:17:12.886143 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000022 (ops 104-108)
I20260812 06:17:12.886181 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000023 (ops 109-113)
I20260812 06:17:12.886217 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000024 (ops 114-118)
I20260812 06:17:12.886253 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000025 (ops 119-123)
I20260812 06:17:12.914350 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: LogGCOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.029s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:12.914913 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling UndoDeltaBlockGCOp(a8fb03bf50f341c999801f46ca9d969f): 473 bytes on disk
I20260812 06:17:12.915505 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: UndoDeltaBlockGCOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.916191 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=3.181125
I20260812 06:17:12.934763 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.018s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7762,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:12.935297 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:12.945648 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3809,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.946269 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:13.137120 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.191s	user 0.134s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795400,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":601,"lbm_read_time_us":14390,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38859,"lbm_writes_lt_1ms":643,"mutex_wait_us":279,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:17:13.137814 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=14.095187
I20260812 06:17:13.187088 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.049s	user 0.039s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20424,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.187707 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:13.203545 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.204088 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:13.368980 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.165s	user 0.124s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":11428,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30927,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:17:13.369963 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=11.118625
I20260812 06:17:13.419281 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.048s	user 0.026s	sys 0.017s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":20920,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:13.419953 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:13.430456 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.431068 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:13.587592 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.156s	user 0.112s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":71,"lbm_read_time_us":12258,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26837,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:13.588285 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=11.118625
I20260812 06:17:13.627142 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.039s	user 0.010s	sys 0.024s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16494,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:13.627801 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:13.642627 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5806,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.645807 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:13.791703 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.146s	user 0.110s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590337,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1241,"lbm_read_time_us":7923,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27532,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2000}
I20260812 06:17:13.792428 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=11.118625
I20260812 06:17:13.839267 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.046s	user 0.012s	sys 0.028s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17823,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:13.839921 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:13.853536 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.854125 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:13.865849 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4021,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.866571 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:14.020218 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.153s	user 0.127s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692870,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":389,"lbm_read_time_us":10064,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29755,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:17:14.020800 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=14.095187
I20260812 06:17:14.071547 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.051s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22555,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.072113 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:14.085309 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.086606 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:14.266301 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.179s	user 0.139s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":288,"lbm_read_time_us":10283,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33835,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:14.267120 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=14.095187
I20260812 06:17:14.335518 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.068s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25878,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.336030 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:14.348635 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4430,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.349139 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushMRSOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:14.379457 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushMRSOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1127,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1768,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:14.380146 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling LogGCOp(a8fb03bf50f341c999801f46ca9d969f): free 120553614 bytes of WAL
I20260812 06:17:14.380362 12917 log_reader.cc:385] T a8fb03bf50f341c999801f46ca9d969f: removed 12 log segments from log reader
I20260812 06:17:14.380403 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000026 (ops 124-128)
I20260812 06:17:14.380431 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000027 (ops 129-132)
I20260812 06:17:14.380519 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000028 (ops 133-137)
I20260812 06:17:14.380580 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000029 (ops 138-142)
I20260812 06:17:14.380618 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000030 (ops 143-147)
I20260812 06:17:14.380657 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000031 (ops 148-152)
I20260812 06:17:14.380698 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000032 (ops 153-156)
I20260812 06:17:14.380736 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000033 (ops 157-161)
I20260812 06:17:14.380780 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000034 (ops 162-166)
I20260812 06:17:14.380821 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000035 (ops 167-171)
I20260812 06:17:14.380860 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000036 (ops 172-176)
I20260812 06:17:14.380900 12917 log.cc:1079] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/a8fb03bf50f341c999801f46ca9d969f/wal-000000037 (ops 177-181)
I20260812 06:17:14.406404 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: LogGCOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:14.406937 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling UndoDeltaBlockGCOp(a8fb03bf50f341c999801f46ca9d969f): 472 bytes on disk
I20260812 06:17:14.407584 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: UndoDeltaBlockGCOp(a8fb03bf50f341c999801f46ca9d969f) 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:14.408152 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=3.181125
I20260812 06:17:14.422998 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.015s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5254,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:14.423522 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:14.433729 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3708,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.434177 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:14.660005 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.226s	user 0.162s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897809,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":542,"lbm_read_time_us":17096,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40426,"lbm_writes_lt_1ms":743,"mutex_wait_us":56,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:17:14.660600 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=15.087375
I20260812 06:17:14.715716 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.055s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":24101,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:14.716298 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:14.739030 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.023s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4817,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.739634 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f): perf score=2.188937
I20260812 06:17:14.752221 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: FlushDeltaMemStoresOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.752821 13013 maintenance_manager.cc:419] P 5c6841b0845044eb801dd8606ea1bc1d: Scheduling MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f): perf score=1.000000
I20260812 06:17:14.837674 12763 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.098s	user 1.866s	sys 0.118s
I20260812 06:17:14.910890 12763 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.001s	sys 0.000s
I20260812 06:17:14.911767 12763 tablet_server.cc:179] TabletServer@127.12.118.193:0 shutting down...
I20260812 06:17:14.925357 12917 maintenance_manager.cc:643] P 5c6841b0845044eb801dd8606ea1bc1d: MajorDeltaCompactionOp(a8fb03bf50f341c999801f46ca9d969f) complete. Timing: real 0.172s	user 0.144s	sys 0.027s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":544,"lbm_read_time_us":12991,"lbm_reads_lt_1ms":669,"lbm_write_time_us":33696,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":3000}
I20260812 06:17:14.926295 12763 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:14.926891 12763 tablet_replica.cc:333] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d: stopping tablet replica
I20260812 06:17:14.927132 12763 raft_consensus.cc:2243] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.927372 12763 raft_consensus.cc:2272] T a8fb03bf50f341c999801f46ca9d969f P 5c6841b0845044eb801dd8606ea1bc1d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.945226 12763 tablet_server.cc:196] TabletServer@127.12.118.193:0 shutdown complete.
I20260812 06:17:14.979607 12763 master.cc:562] Master@127.12.118.254:41791 shutting down...
I20260812 06:17:14.984628 12763 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.984876 12763 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.984995 12763 tablet_replica.cc:333] T 00000000000000000000000000000000 P 79a4cd0e2a024732ba8651928f314bc7: stopping tablet replica
I20260812 06:17:14.998400 12763 master.cc:584] Master@127.12.118.254:41791 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5674 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:15.092252 12763 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.118.254:43129
I20260812 06:17:15.092762 12763 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:15.095410 12763 server_base.cc:1061] running on GCE node
W20260812 06:17:15.095323 13070 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:15.095574 13066 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:15.095641 13065 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:15.095889 12763 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:15.095937 12763 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:15.095961 12763 hybrid_clock.cc:648] HybridClock initialized: now 1786515435095961 us; error 0 us; skew 500 ppm
I20260812 06:17:15.097190 12763 webserver.cc:533] Webserver started at http://127.12.118.254:33625/ using document root <none> and password file <none>
I20260812 06:17:15.097486 12763 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:15.097584 12763 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:15.097646 12763 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:15.098093 12763 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/master-0-root/instance:
uuid: "e16a8f1625c04df79e3b0998e8ad41bf"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-c12x"
I20260812 06:17:15.099992 12763 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:15.101114 13082 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:15.101445 12763 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:15.101514 12763 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/master-0-root
uuid: "e16a8f1625c04df79e3b0998e8ad41bf"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-c12x"
I20260812 06:17:15.101572 12763 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-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:15.122402 12763 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:15.122821 12763 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:15.126711 12763 rpc_server.cc:307] RPC server started. Bound to: 127.12.118.254:43129
I20260812 06:17:15.128872 13165 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.118.254:43129 every 8 connection(s)
I20260812 06:17:15.129504 13166 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:15.144212 13166 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf: Bootstrap starting.
I20260812 06:17:15.145212 13166 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:15.146399 13166 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf: No bootstrap required, opened a new log
I20260812 06:17:15.146826 13166 raft_consensus.cc:359] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e16a8f1625c04df79e3b0998e8ad41bf" member_type: VOTER }
I20260812 06:17:15.146952 13166 raft_consensus.cc:385] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:15.147004 13166 raft_consensus.cc:740] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e16a8f1625c04df79e3b0998e8ad41bf, State: Initialized, Role: FOLLOWER
I20260812 06:17:15.147171 13166 consensus_queue.cc:260] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [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: "e16a8f1625c04df79e3b0998e8ad41bf" member_type: VOTER }
I20260812 06:17:15.147265 13166 raft_consensus.cc:399] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:15.147317 13166 raft_consensus.cc:493] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:15.147375 13166 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:15.148253 13166 raft_consensus.cc:515] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e16a8f1625c04df79e3b0998e8ad41bf" member_type: VOTER }
I20260812 06:17:15.148412 13166 leader_election.cc:304] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [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: e16a8f1625c04df79e3b0998e8ad41bf; no voters: 
I20260812 06:17:15.148650 13166 leader_election.cc:290] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:15.148867 13171 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:15.149155 13171 raft_consensus.cc:697] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 1 LEADER]: Becoming Leader. State: Replica: e16a8f1625c04df79e3b0998e8ad41bf, State: Running, Role: LEADER
I20260812 06:17:15.149185 13166 sys_catalog.cc:565] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:15.149335 13171 consensus_queue.cc:237] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [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: "e16a8f1625c04df79e3b0998e8ad41bf" member_type: VOTER }
I20260812 06:17:15.149868 13173 sys_catalog.cc:455] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [sys.catalog]: SysCatalogTable state changed. Reason: New leader e16a8f1625c04df79e3b0998e8ad41bf. Latest consensus state: current_term: 1 leader_uuid: "e16a8f1625c04df79e3b0998e8ad41bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e16a8f1625c04df79e3b0998e8ad41bf" member_type: VOTER } }
I20260812 06:17:15.149853 13172 sys_catalog.cc:455] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e16a8f1625c04df79e3b0998e8ad41bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e16a8f1625c04df79e3b0998e8ad41bf" member_type: VOTER } }
I20260812 06:17:15.150058 13172 sys_catalog.cc:458] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:15.150092 13173 sys_catalog.cc:458] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:15.150620 13181 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:15.151372 13181 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:15.151736 12763 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:15.153434 13181 catalog_manager.cc:1383] Generated new cluster ID: 61334d8abd4943b08ca435ee55fdff53
I20260812 06:17:15.153502 13181 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:15.162470 13181 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:15.163084 13181 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:15.174770 13181 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf: Generated new TSK 0
I20260812 06:17:15.175031 13181 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:15.184386 12763 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:15.186795 13195 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:15.186892 12763 server_base.cc:1061] running on GCE node
W20260812 06:17:15.186905 13197 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:15.186926 13194 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:15.187206 12763 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:15.187254 12763 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:15.187296 12763 hybrid_clock.cc:648] HybridClock initialized: now 1786515435187295 us; error 0 us; skew 500 ppm
I20260812 06:17:15.188350 12763 webserver.cc:533] Webserver started at http://127.12.118.193:39553/ using document root <none> and password file <none>
I20260812 06:17:15.188660 12763 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:15.188736 12763 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:15.188850 12763 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:15.189302 12763 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/instance:
uuid: "b8c76f9f473743d4a6d3e745e84a9c6b"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-c12x"
I20260812 06:17:15.190814 12763 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:15.191865 13206 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:15.192135 12763 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:15.192212 12763 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root
uuid: "b8c76f9f473743d4a6d3e745e84a9c6b"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-c12x"
I20260812 06:17:15.192310 12763 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-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:15.212512 12763 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:15.212988 12763 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:15.213359 12763 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:15.213935 12763 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:15.214002 12763 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.214061 12763 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:15.214120 12763 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.219063 12763 rpc_server.cc:307] RPC server started. Bound to: 127.12.118.193:35997
I20260812 06:17:15.219092 13299 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.118.193:35997 every 8 connection(s)
I20260812 06:17:15.228824 13300 heartbeater.cc:344] Connected to a master server at 127.12.118.254:43129
I20260812 06:17:15.228945 13300 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:15.229269 13300 heartbeater.cc:507] Master 127.12.118.254:43129 requested a full tablet report, sending...
I20260812 06:17:15.230126 13106 ts_manager.cc:194] Registered new tserver with Master: b8c76f9f473743d4a6d3e745e84a9c6b (127.12.118.193:35997)
I20260812 06:17:15.230760 12763 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011175476s
I20260812 06:17:15.231061 13106 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57524
I20260812 06:17:15.238871 13106 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57536:
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:15.247570 13247 tablet_service.cc:1511] Processing CreateTablet for tablet 0c9af4a1c4734c72a0319d5ef4bbd29d (DEFAULT_TABLE table=heavy-update-compaction-test [id=c4ff08b3ba8a48a982cf93100f5d38df]), partition=
I20260812 06:17:15.247892 13247 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0c9af4a1c4734c72a0319d5ef4bbd29d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:15.249966 13316 tablet_bootstrap.cc:492] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Bootstrap starting.
I20260812 06:17:15.251024 13316 tablet_bootstrap.cc:654] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:15.252195 13316 tablet_bootstrap.cc:492] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: No bootstrap required, opened a new log
I20260812 06:17:15.252278 13316 ts_tablet_manager.cc:1403] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:15.252738 13316 raft_consensus.cc:359] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b8c76f9f473743d4a6d3e745e84a9c6b" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 35997 } }
I20260812 06:17:15.252830 13316 raft_consensus.cc:385] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:15.252851 13316 raft_consensus.cc:740] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b8c76f9f473743d4a6d3e745e84a9c6b, State: Initialized, Role: FOLLOWER
I20260812 06:17:15.253021 13316 consensus_queue.cc:260] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [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: "b8c76f9f473743d4a6d3e745e84a9c6b" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 35997 } }
I20260812 06:17:15.253147 13316 raft_consensus.cc:399] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:15.253228 13316 raft_consensus.cc:493] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:15.253289 13316 raft_consensus.cc:3060] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:15.254189 13316 raft_consensus.cc:515] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b8c76f9f473743d4a6d3e745e84a9c6b" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 35997 } }
I20260812 06:17:15.254304 13316 leader_election.cc:304] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [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: b8c76f9f473743d4a6d3e745e84a9c6b; no voters: 
I20260812 06:17:15.254568 13316 leader_election.cc:290] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:15.254662 13318 raft_consensus.cc:2804] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:15.254963 13318 raft_consensus.cc:697] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 1 LEADER]: Becoming Leader. State: Replica: b8c76f9f473743d4a6d3e745e84a9c6b, State: Running, Role: LEADER
I20260812 06:17:15.255012 13316 ts_tablet_manager.cc:1434] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:15.254990 13300 heartbeater.cc:499] Master 127.12.118.254:43129 was elected leader, sending a full tablet report...
I20260812 06:17:15.255167 13318 consensus_queue.cc:237] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [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: "b8c76f9f473743d4a6d3e745e84a9c6b" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 35997 } }
I20260812 06:17:15.256692 13106 catalog_manager.cc:5719] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b reported cstate change: term changed from 0 to 1, leader changed from <none> to b8c76f9f473743d4a6d3e745e84a9c6b (127.12.118.193). New cstate: current_term: 1 leader_uuid: "b8c76f9f473743d4a6d3e745e84a9c6b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b8c76f9f473743d4a6d3e745e84a9c6b" member_type: VOTER last_known_addr { host: "127.12.118.193" port: 35997 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:15.317214 12763 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.014s	sys 0.008s
I20260812 06:17:15.470135 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushMRSOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=19.054940
I20260812 06:17:15.641601 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushMRSOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.171s	user 0.111s	sys 0.057s Metrics: {"bytes_written":13086952,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":190,"dirs.run_wall_time_us":793,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44627,"lbm_writes_lt_1ms":776,"mutex_wait_us":1118,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"update_count":1595}
I20260812 06:17:15.642221 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d): free 20743880 bytes of WAL
I20260812 06:17:15.642452 13212 log_reader.cc:385] T 0c9af4a1c4734c72a0319d5ef4bbd29d: removed 2 log segments from log reader
I20260812 06:17:15.642493 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000001 (ops 1-6)
I20260812 06:17:15.642522 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000002 (ops 7-11)
I20260812 06:17:15.647259 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:15.647611 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:15.661078 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:17:15.661509 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:15.671131 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3489,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.671622 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling UndoDeltaBlockGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d): 16411393 bytes on disk
I20260812 06:17:15.672030 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: UndoDeltaBlockGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.672413 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:15.838788 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.166s	user 0.130s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774791,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":80,"lbm_read_time_us":11542,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31919,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":334,"threads_started":5,"update_count":2500}
I20260812 06:17:15.839588 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=11.118625
I20260812 06:17:15.888500 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.049s	user 0.039s	sys 0.004s Metrics: {"bytes_written":12512611,"delete_count":0,"lbm_write_time_us":18716,"lbm_writes_lt_1ms":308,"reinsert_count":0,"update_count":1525}
I20260812 06:17:15.888985 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:15.902155 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:17:15.902711 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:16.040613 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.138s	user 0.110s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1034,"lbm_read_time_us":8769,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29370,"lbm_writes_lt_1ms":443,"mutex_wait_us":391,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:16.041215 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=10.126437
I20260812 06:17:16.086736 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.045s	user 0.031s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15698,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.087321 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:16.098237 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4444,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.098744 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:16.253782 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.155s	user 0.098s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":11411,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27207,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":78208,"update_count":2000}
I20260812 06:17:16.254458 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=10.126437
I20260812 06:17:16.285620 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.031s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13459,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.286070 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:16.302498 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.016s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.303234 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:16.436841 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.133s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1146,"lbm_read_time_us":10019,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25321,"lbm_writes_lt_1ms":443,"mutex_wait_us":329,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2000}
I20260812 06:17:16.437772 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=10.126437
I20260812 06:17:16.476701 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.039s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19168,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.477254 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:16.490427 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4972,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.490935 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:16.632005 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.141s	user 0.108s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":818,"lbm_read_time_us":10369,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27072,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":82560,"update_count":2000}
I20260812 06:17:16.632673 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=10.126437
I20260812 06:17:16.678900 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.046s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17169,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.679389 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:16.690435 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.691251 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:16.816035 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.125s	user 0.089s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":790,"lbm_read_time_us":9618,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22107,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:17:16.816829 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=10.126437
I20260812 06:17:16.867013 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.050s	user 0.024s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17311,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.867755 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:16.885380 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.886049 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushMRSOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:16.920100 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushMRSOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.034s	user 0.029s	sys 0.005s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":310,"dirs.run_wall_time_us":1195,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1789,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:16.920781 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:17.092183 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.171s	user 0.102s	sys 0.058s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":167,"lbm_read_time_us":11112,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25172,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:17:17.093004 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d): free 120100337 bytes of WAL
I20260812 06:17:17.093250 13212 log_reader.cc:385] T 0c9af4a1c4734c72a0319d5ef4bbd29d: removed 12 log segments from log reader
I20260812 06:17:17.093313 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000003 (ops 12-16)
I20260812 06:17:17.093398 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000004 (ops 17-20)
I20260812 06:17:17.093470 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000005 (ops 21-25)
I20260812 06:17:17.093524 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000006 (ops 26-30)
I20260812 06:17:17.093551 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000007 (ops 31-35)
I20260812 06:17:17.093581 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000008 (ops 36-40)
I20260812 06:17:17.093654 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000009 (ops 41-44)
I20260812 06:17:17.093904 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000010 (ops 45-49)
I20260812 06:17:17.094024 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000011 (ops 50-54)
I20260812 06:17:17.094184 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000012 (ops 55-58)
I20260812 06:17:17.094285 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000013 (ops 59-63)
I20260812 06:17:17.094329 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000014 (ops 64-68)
I20260812 06:17:17.122471 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:17.125929 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling UndoDeltaBlockGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d): 462 bytes on disk
I20260812 06:17:17.127586 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: UndoDeltaBlockGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.128445 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=14.095187
I20260812 06:17:17.182823 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.054s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16532978,"delete_count":0,"lbm_write_time_us":24589,"lbm_writes_lt_1ms":406,"mutex_wait_us":347,"reinsert_count":0,"update_count":2015}
I20260812 06:17:17.183537 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=3.181125
I20260812 06:17:17.216617 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.033s	user 0.006s	sys 0.023s Metrics: {"bytes_written":4389837,"delete_count":0,"lbm_write_time_us":7738,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:17:17.217267 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:17.233177 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5714,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.233908 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:17.449528 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.215s	user 0.125s	sys 0.090s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":248,"lbm_read_time_us":15824,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35470,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":3000}
I20260812 06:17:17.450161 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=14.095187
I20260812 06:17:17.510347 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.060s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22599,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.510854 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=3.181125
I20260812 06:17:17.539247 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.028s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7786,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:17.539786 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:17.549942 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3940,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.550675 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:17.776360 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.225s	user 0.145s	sys 0.079s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":256,"lbm_read_time_us":16898,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35405,"lbm_writes_lt_1ms":643,"mutex_wait_us":48,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":3000}
I20260812 06:17:17.777109 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=14.095187
I20260812 06:17:17.819933 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.043s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19406,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.820597 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:17.837832 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.838434 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:18.020517 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.182s	user 0.127s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":367,"lbm_read_time_us":14092,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31643,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:17:18.021267 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=14.095187
I20260812 06:17:18.084602 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.063s	user 0.038s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21570,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.085287 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:18.096225 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4290,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.096680 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:18.278514 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.182s	user 0.103s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":12727,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31245,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2500}
I20260812 06:17:18.279369 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=11.118625
I20260812 06:17:18.322395 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.043s	user 0.030s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19147,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:18.322966 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:18.334125 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.334606 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:18.502146 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.167s	user 0.112s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":732,"lbm_read_time_us":11249,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27002,"lbm_writes_lt_1ms":443,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2000}
I20260812 06:17:18.502727 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=10.126437
I20260812 06:17:18.549829 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.047s	user 0.032s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17892,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.550544 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:18.563917 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.013s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.564744 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushMRSOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:18.596728 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushMRSOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.032s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":153,"dirs.run_wall_time_us":1175,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2504,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:18.597584 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d): free 117302579 bytes of WAL
I20260812 06:17:18.597858 13212 log_reader.cc:385] T 0c9af4a1c4734c72a0319d5ef4bbd29d: removed 12 log segments from log reader
I20260812 06:17:18.597918 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000015 (ops 69-73)
I20260812 06:17:18.597956 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000016 (ops 74-78)
I20260812 06:17:18.597992 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000017 (ops 79-83)
I20260812 06:17:18.598026 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000018 (ops 84-88)
I20260812 06:17:18.598049 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000019 (ops 89-93)
I20260812 06:17:18.598073 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000020 (ops 94-98)
I20260812 06:17:18.598095 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000021 (ops 99-102)
I20260812 06:17:18.598127 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000022 (ops 103-107)
I20260812 06:17:18.598153 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000023 (ops 108-112)
I20260812 06:17:18.598178 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000024 (ops 113-116)
I20260812 06:17:18.598201 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000025 (ops 117-121)
I20260812 06:17:18.598237 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000026 (ops 122-126)
I20260812 06:17:18.628752 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:18.629315 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:18.647344 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.018s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.647898 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d): free 11564883 bytes of WAL
I20260812 06:17:18.648159 13212 log_reader.cc:385] T 0c9af4a1c4734c72a0319d5ef4bbd29d: removed 1 log segments from log reader
I20260812 06:17:18.648221 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000027 (ops 127-130)
I20260812 06:17:18.651423 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.003s	user 0.003s	sys 0.000s Metrics: {}
I20260812 06:17:18.651798 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:18.667038 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.667603 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling UndoDeltaBlockGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d): 470 bytes on disk
I20260812 06:17:18.668205 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: UndoDeltaBlockGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":133,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.668886 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:18.864817 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.196s	user 0.157s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1301,"lbm_read_time_us":14301,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35820,"lbm_writes_lt_1ms":643,"mutex_wait_us":333,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17920,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:17:18.865509 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=14.095187
I20260812 06:17:18.929214 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.064s	user 0.024s	sys 0.037s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":30774,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.929708 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:18.952147 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.022s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5579,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.952666 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:19.149632 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.197s	user 0.128s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":822,"lbm_read_time_us":12491,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29028,"lbm_writes_lt_1ms":543,"mutex_wait_us":455,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":444160,"update_count":2500}
I20260812 06:17:19.150216 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=14.095187
I20260812 06:17:19.200212 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.050s	user 0.017s	sys 0.031s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22073,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.200841 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:19.226984 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.026s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.227589 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:19.240654 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.241164 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:19.464982 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.224s	user 0.140s	sys 0.078s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877223,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":259,"lbm_read_time_us":14301,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35748,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":56960,"update_count":3000}
I20260812 06:17:19.465778 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=14.095187
I20260812 06:17:19.512912 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.047s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20577,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.513652 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:19.539745 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.026s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.540306 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:19.555536 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.556192 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:19.786886 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.230s	user 0.161s	sys 0.068s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":845,"lbm_read_time_us":17061,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38929,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3000}
I20260812 06:17:19.787621 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=14.095187
I20260812 06:17:19.856230 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.068s	user 0.041s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24481,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.856997 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:19.869141 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.869611 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:20.062031 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.192s	user 0.112s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":623,"lbm_read_time_us":14265,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32728,"lbm_writes_lt_1ms":543,"mutex_wait_us":278,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:20.063337 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=11.118625
I20260812 06:17:20.110775 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.047s	user 0.031s	sys 0.009s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":18384,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:20.111514 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:20.146203 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.034s	user 0.005s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.146895 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:20.158710 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4600,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.159289 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushMRSOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:20.211732 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushMRSOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.052s	user 0.031s	sys 0.005s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":1485,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2597,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:20.212929 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d): free 112239554 bytes of WAL
I20260812 06:17:20.213166 13212 log_reader.cc:385] T 0c9af4a1c4734c72a0319d5ef4bbd29d: removed 11 log segments from log reader
I20260812 06:17:20.213212 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000028 (ops 131-135)
I20260812 06:17:20.213243 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000029 (ops 136-140)
I20260812 06:17:20.213318 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000030 (ops 141-145)
I20260812 06:17:20.213430 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000031 (ops 146-150)
I20260812 06:17:20.213454 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000032 (ops 151-154)
I20260812 06:17:20.213515 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000033 (ops 155-159)
I20260812 06:17:20.213558 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000034 (ops 160-164)
I20260812 06:17:20.213604 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000035 (ops 165-169)
I20260812 06:17:20.213646 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000036 (ops 170-174)
I20260812 06:17:20.213693 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000037 (ops 175-179)
I20260812 06:17:20.213729 13212 log.cc:1079] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: Deleting log segment in path: /tmp/dist-test-taskaZ9IqQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429405613-12763-0/minicluster-data/ts-0-root/wals/0c9af4a1c4734c72a0319d5ef4bbd29d/wal-000000038 (ops 180-184)
I20260812 06:17:20.239655 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: LogGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:20.240198 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:20.270569 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.030s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.271195 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling UndoDeltaBlockGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d): 463 bytes on disk
I20260812 06:17:20.271677 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: UndoDeltaBlockGCOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.272243 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:20.287987 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.016s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.288546 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:20.534827 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.246s	user 0.162s	sys 0.077s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979862,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1007,"lbm_read_time_us":16493,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39456,"lbm_writes_lt_1ms":743,"mutex_wait_us":79,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":108,"threads_started":1,"update_count":3500}
I20260812 06:17:20.537096 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=16.079562
I20260812 06:17:20.582674 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.045s	user 0.018s	sys 0.024s Metrics: {"bytes_written":17599600,"delete_count":0,"lbm_write_time_us":20370,"lbm_writes_lt_1ms":432,"reinsert_count":0,"update_count":2145}
I20260812 06:17:20.583369 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.196750
I20260812 06:17:20.609644 12763 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.292s	user 1.917s	sys 0.209s
I20260812 06:17:20.611096 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.028s	user 0.013s	sys 0.000s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":5648,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:17:20.611585 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=2.188937
I20260812 06:17:20.621371 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: FlushDeltaMemStoresOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.621801 13301 maintenance_manager.cc:419] P b8c76f9f473743d4a6d3e745e84a9c6b: Scheduling MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d): perf score=1.000000
I20260812 06:17:20.685062 12763 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.075s	user 0.003s	sys 0.000s
I20260812 06:17:20.685761 12763 tablet_server.cc:179] TabletServer@127.12.118.193:0 shutting down...
I20260812 06:17:20.785211 13212 maintenance_manager.cc:643] P b8c76f9f473743d4a6d3e745e84a9c6b: MajorDeltaCompactionOp(0c9af4a1c4734c72a0319d5ef4bbd29d) complete. Timing: real 0.163s	user 0.119s	sys 0.044s Metrics: {"cfile_cache_hit":219,"cfile_cache_hit_bytes":8906155,"cfile_cache_miss":414,"cfile_cache_miss_bytes":19971034,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":444,"lbm_read_time_us":9459,"lbm_reads_lt_1ms":446,"lbm_write_time_us":32192,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":3000}
I20260812 06:17:20.786052 12763 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:20.786288 12763 tablet_replica.cc:333] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b: stopping tablet replica
I20260812 06:17:20.786418 12763 raft_consensus.cc:2243] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.786619 12763 raft_consensus.cc:2272] T 0c9af4a1c4734c72a0319d5ef4bbd29d P b8c76f9f473743d4a6d3e745e84a9c6b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.800948 12763 tablet_server.cc:196] TabletServer@127.12.118.193:0 shutdown complete.
I20260812 06:17:20.840507 12763 master.cc:562] Master@127.12.118.254:43129 shutting down...
I20260812 06:17:20.844715 12763 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.844952 12763 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.845050 12763 tablet_replica.cc:333] T 00000000000000000000000000000000 P e16a8f1625c04df79e3b0998e8ad41bf: stopping tablet replica
I20260812 06:17:20.858980 12763 master.cc:584] Master@127.12.118.254:43129 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5864 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11539 ms total)

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