[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:22.679692 23731 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.44.254:42643
I20260812 06:16:22.680802 23731 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:22.681430 23731 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:22.687798 23737 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:22.687829 23741 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:22.687886 23731 server_base.cc:1061] running on GCE node
W20260812 06:16:22.688225 23738 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:22.688791 23731 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:22.688926 23731 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:22.688975 23731 hybrid_clock.cc:648] HybridClock initialized: now 1786515382688973 us; error 0 us; skew 500 ppm
I20260812 06:16:22.690740 23731 webserver.cc:533] Webserver started at http://127.23.44.254:46739/ using document root <none> and password file <none>
I20260812 06:16:22.691249 23731 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:22.691308 23731 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:22.691510 23731 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:22.693252 23731 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/master-0-root/instance:
uuid: "4d5a4ff412254c8d8e570fb4561b42ba"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-65mx"
I20260812 06:16:22.697204 23731 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:16:22.699466 23750 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.700680 23731 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:22.700815 23731 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/master-0-root
uuid: "4d5a4ff412254c8d8e570fb4561b42ba"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-65mx"
I20260812 06:16:22.700932 23731 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:22.726159 23731 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:22.726871 23731 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:22.727074 23731 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:22.735146 23731 rpc_server.cc:307] RPC server started. Bound to: 127.23.44.254:42643
I20260812 06:16:22.735162 23810 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.44.254:42643 every 8 connection(s)
I20260812 06:16:22.737601 23811 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:22.743181 23811 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba: Bootstrap starting.
I20260812 06:16:22.745734 23811 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:22.746718 23811 log.cc:826] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:22.748842 23811 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba: No bootstrap required, opened a new log
I20260812 06:16:22.751865 23811 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d5a4ff412254c8d8e570fb4561b42ba" member_type: VOTER }
I20260812 06:16:22.752060 23811 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:22.752153 23811 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4d5a4ff412254c8d8e570fb4561b42ba, State: Initialized, Role: FOLLOWER
I20260812 06:16:22.752836 23811 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [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: "4d5a4ff412254c8d8e570fb4561b42ba" member_type: VOTER }
I20260812 06:16:22.753024 23811 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:22.753103 23811 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:22.753288 23811 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:22.754143 23811 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d5a4ff412254c8d8e570fb4561b42ba" member_type: VOTER }
I20260812 06:16:22.754611 23811 leader_election.cc:304] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [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: 4d5a4ff412254c8d8e570fb4561b42ba; no voters: 
I20260812 06:16:22.754973 23811 leader_election.cc:290] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:22.755129 23814 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:22.755409 23814 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 1 LEADER]: Becoming Leader. State: Replica: 4d5a4ff412254c8d8e570fb4561b42ba, State: Running, Role: LEADER
I20260812 06:16:22.755908 23814 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [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: "4d5a4ff412254c8d8e570fb4561b42ba" member_type: VOTER }
I20260812 06:16:22.756073 23811 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:22.758124 23817 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4d5a4ff412254c8d8e570fb4561b42ba. Latest consensus state: current_term: 1 leader_uuid: "4d5a4ff412254c8d8e570fb4561b42ba" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d5a4ff412254c8d8e570fb4561b42ba" member_type: VOTER } }
I20260812 06:16:22.758150 23815 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4d5a4ff412254c8d8e570fb4561b42ba" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d5a4ff412254c8d8e570fb4561b42ba" member_type: VOTER } }
I20260812 06:16:22.758256 23817 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.758265 23815 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.758543 23731 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:16:22.760685 23831 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:22.760766 23831 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:22.760836 23830 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:22.761543 23830 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:22.766481 23830 catalog_manager.cc:1383] Generated new cluster ID: 7f8b7b7a25dd41ef983535ab0b397241
I20260812 06:16:22.766573 23830 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:22.781080 23830 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:22.782011 23830 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:22.800230 23830 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba: Generated new TSK 0
I20260812 06:16:22.801087 23830 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:22.823571 23731 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:22.826854 23835 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:22.826867 23838 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:22.826862 23836 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:22.827211 23731 server_base.cc:1061] running on GCE node
I20260812 06:16:22.827404 23731 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:22.827461 23731 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:22.827497 23731 hybrid_clock.cc:648] HybridClock initialized: now 1786515382827495 us; error 0 us; skew 500 ppm
I20260812 06:16:22.828502 23731 webserver.cc:533] Webserver started at http://127.23.44.193:43467/ using document root <none> and password file <none>
I20260812 06:16:22.828733 23731 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:22.828810 23731 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:22.828894 23731 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:22.829324 23731 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/instance:
uuid: "ab5fde3cfb5c4cc493f60097ef4e7967"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-65mx"
I20260812 06:16:22.830874 23731 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:22.831889 23846 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.832147 23731 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:22.832223 23731 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root
uuid: "ab5fde3cfb5c4cc493f60097ef4e7967"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-65mx"
I20260812 06:16:22.832317 23731 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:22.840335 23731 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:22.840829 23731 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:22.841363 23731 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:22.842245 23731 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:22.842296 23731 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.842366 23731 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:22.842404 23731 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.849392 23731 rpc_server.cc:307] RPC server started. Bound to: 127.23.44.193:34621
I20260812 06:16:22.849424 23924 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.44.193:34621 every 8 connection(s)
I20260812 06:16:22.862779 23925 heartbeater.cc:344] Connected to a master server at 127.23.44.254:42643
I20260812 06:16:22.863075 23925 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:22.863565 23925 heartbeater.cc:507] Master 127.23.44.254:42643 requested a full tablet report, sending...
I20260812 06:16:22.865044 23768 ts_manager.cc:194] Registered new tserver with Master: ab5fde3cfb5c4cc493f60097ef4e7967 (127.23.44.193:34621)
I20260812 06:16:22.865156 23731 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015099943s
I20260812 06:16:22.866291 23768 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42368
I20260812 06:16:22.875324 23768 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42384:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:22.902882 23882 tablet_service.cc:1511] Processing CreateTablet for tablet f0ade73b8c294c7f82a9f4b585445f83 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ac6aa4f9f90d47de98a92d6d9e4d0f8f]), partition=
I20260812 06:16:22.903529 23882 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f0ade73b8c294c7f82a9f4b585445f83. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:22.907264 23940 tablet_bootstrap.cc:492] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Bootstrap starting.
I20260812 06:16:22.908504 23940 tablet_bootstrap.cc:654] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:22.910256 23940 tablet_bootstrap.cc:492] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: No bootstrap required, opened a new log
I20260812 06:16:22.910392 23940 ts_tablet_manager.cc:1403] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:22.911162 23940 raft_consensus.cc:359] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab5fde3cfb5c4cc493f60097ef4e7967" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 34621 } }
I20260812 06:16:22.911299 23940 raft_consensus.cc:385] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:22.911369 23940 raft_consensus.cc:740] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ab5fde3cfb5c4cc493f60097ef4e7967, State: Initialized, Role: FOLLOWER
I20260812 06:16:22.911532 23940 consensus_queue.cc:260] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [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: "ab5fde3cfb5c4cc493f60097ef4e7967" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 34621 } }
I20260812 06:16:22.911648 23940 raft_consensus.cc:399] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:22.911703 23940 raft_consensus.cc:493] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:22.911758 23940 raft_consensus.cc:3060] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:22.912886 23940 raft_consensus.cc:515] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab5fde3cfb5c4cc493f60097ef4e7967" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 34621 } }
I20260812 06:16:22.913062 23940 leader_election.cc:304] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [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: ab5fde3cfb5c4cc493f60097ef4e7967; no voters: 
I20260812 06:16:22.913321 23940 leader_election.cc:290] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:22.913434 23943 raft_consensus.cc:2804] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:22.913688 23943 raft_consensus.cc:697] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 1 LEADER]: Becoming Leader. State: Replica: ab5fde3cfb5c4cc493f60097ef4e7967, State: Running, Role: LEADER
I20260812 06:16:22.913816 23940 ts_tablet_manager.cc:1434] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:16:22.913902 23943 consensus_queue.cc:237] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [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: "ab5fde3cfb5c4cc493f60097ef4e7967" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 34621 } }
I20260812 06:16:22.914163 23925 heartbeater.cc:499] Master 127.23.44.254:42643 was elected leader, sending a full tablet report...
I20260812 06:16:22.917630 23768 catalog_manager.cc:5719] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 reported cstate change: term changed from 0 to 1, leader changed from <none> to ab5fde3cfb5c4cc493f60097ef4e7967 (127.23.44.193). New cstate: current_term: 1 leader_uuid: "ab5fde3cfb5c4cc493f60097ef4e7967" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab5fde3cfb5c4cc493f60097ef4e7967" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 34621 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:23.024751 23731 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.096s	user 0.021s	sys 0.041s
I20260812 06:16:23.100829 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushMRSOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.125253
I20260812 06:16:23.251534 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushMRSOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.150s	user 0.101s	sys 0.045s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":224,"delete_count":0,"dirs.queue_time_us":292,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1223,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38068,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":456,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":157,"threads_started":1,"update_count":1000}
I20260812 06:16:23.252939 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling LogGCOp(f0ade73b8c294c7f82a9f4b585445f83): free 8725963 bytes of WAL
I20260812 06:16:23.253363 23853 log_reader.cc:385] T f0ade73b8c294c7f82a9f4b585445f83: removed 1 log segments from log reader
I20260812 06:16:23.253445 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000001 (ops 1-6)
I20260812 06:16:23.256028 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: LogGCOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:23.256403 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:23.281788 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.025s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.282328 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:23.298652 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.299329 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling UndoDeltaBlockGCOp(f0ade73b8c294c7f82a9f4b585445f83): 8206537 bytes on disk
I20260812 06:16:23.300019 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: UndoDeltaBlockGCOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:16:23.300467 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:23.458129 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.157s	user 0.119s	sys 0.036s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20590466,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":981,"lbm_read_time_us":10571,"lbm_reads_lt_1ms":469,"lbm_write_time_us":30138,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":360,"threads_started":5,"update_count":2000}
I20260812 06:16:23.458732 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:23.509824 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.051s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18679,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.510340 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:23.522204 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.522840 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:23.654840 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.132s	user 0.088s	sys 0.039s 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":226,"lbm_read_time_us":9080,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29543,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:16:23.655597 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=11.118625
I20260812 06:16:23.705533 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.050s	user 0.030s	sys 0.019s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":19016,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:23.706117 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:23.716780 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4065,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:23.717264 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:23.865882 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.148s	user 0.096s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":558,"lbm_read_time_us":11631,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25073,"lbm_writes_lt_1ms":443,"mutex_wait_us":121,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":141440,"update_count":2000}
I20260812 06:16:23.866416 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:23.922644 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.056s	user 0.028s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19781,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:23.923177 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:23.935436 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.936173 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:24.071061 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.135s	user 0.114s	sys 0.020s 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":529,"lbm_read_time_us":9219,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30059,"lbm_writes_lt_1ms":443,"mutex_wait_us":95,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:24.071566 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:24.123713 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.052s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18678,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.124321 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:24.137903 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4843,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.138537 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:24.274026 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.135s	user 0.103s	sys 0.032s 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":604,"lbm_read_time_us":10127,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28226,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:16:24.274698 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:24.333654 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.059s	user 0.036s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20884,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.334239 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:24.346666 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.347308 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:24.515368 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.168s	user 0.121s	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":231,"lbm_read_time_us":11559,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27509,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:24.516036 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:24.575881 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.060s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":35037,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.576493 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:24.588900 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.589422 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushMRSOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:24.624248 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushMRSOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1476,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2318,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:24.625260 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling LogGCOp(f0ade73b8c294c7f82a9f4b585445f83): free 112239310 bytes of WAL
I20260812 06:16:24.625600 23853 log_reader.cc:385] T f0ade73b8c294c7f82a9f4b585445f83: removed 11 log segments from log reader
I20260812 06:16:24.625675 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000002 (ops 7-11)
I20260812 06:16:24.625730 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000003 (ops 12-16)
I20260812 06:16:24.625785 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000004 (ops 17-21)
I20260812 06:16:24.625833 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000005 (ops 22-26)
I20260812 06:16:24.625880 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000006 (ops 27-31)
I20260812 06:16:24.625921 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000007 (ops 32-36)
I20260812 06:16:24.625957 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000008 (ops 37-41)
I20260812 06:16:24.625994 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000009 (ops 42-46)
I20260812 06:16:24.626030 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000010 (ops 47-50)
I20260812 06:16:24.626056 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000011 (ops 51-55)
I20260812 06:16:24.626083 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000012 (ops 56-60)
I20260812 06:16:24.653515 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: LogGCOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.028s	user 0.002s	sys 0.025s Metrics: {}
I20260812 06:16:24.654232 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling UndoDeltaBlockGCOp(f0ade73b8c294c7f82a9f4b585445f83): 448 bytes on disk
I20260812 06:16:24.654716 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: UndoDeltaBlockGCOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:16:24.655241 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=3.181125
I20260812 06:16:24.678882 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.024s	user 0.007s	sys 0.013s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4848,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:24.679560 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling LogGCOp(f0ade73b8c294c7f82a9f4b585445f83): free 11564875 bytes of WAL
I20260812 06:16:24.679831 23853 log_reader.cc:385] T f0ade73b8c294c7f82a9f4b585445f83: removed 1 log segments from log reader
I20260812 06:16:24.679894 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000013 (ops 61-64)
I20260812 06:16:24.683269 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: LogGCOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:24.683768 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:24.694375 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.010s	user 0.004s	sys 0.004s 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:16:24.694880 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:24.898900 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.204s	user 0.140s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795399,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":415,"lbm_read_time_us":14878,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32512,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4608,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:16:24.899592 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=14.095187
I20260812 06:16:24.962613 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.063s	user 0.037s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23411,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:24.963158 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:24.974623 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.975188 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:25.165854 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.190s	user 0.102s	sys 0.086s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":14348,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33491,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:25.166495 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=11.118625
I20260812 06:16:25.220268 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.053s	user 0.024s	sys 0.025s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":23715,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:16:25.220863 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:25.251807 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.031s	user 0.009s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4579,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:25.252360 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:25.263535 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4366,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.263998 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:25.440981 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.177s	user 0.112s	sys 0.064s 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":1111,"lbm_read_time_us":12697,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32082,"lbm_writes_lt_1ms":543,"mutex_wait_us":380,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:16:25.441540 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:25.477294 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.036s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15935,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.478027 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:25.495536 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6795,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.496096 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:25.624336 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.128s	user 0.107s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":458,"lbm_read_time_us":10047,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24043,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:16:25.625046 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:25.670341 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.045s	user 0.016s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17951,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1500}
I20260812 06:16:25.670816 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:25.684913 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5151,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.685922 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:25.846221 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.159s	user 0.128s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1513,"lbm_read_time_us":10505,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29015,"lbm_writes_lt_1ms":443,"mutex_wait_us":1268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:16:25.847460 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:25.891340 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.043s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15546,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:25.891893 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:25.903187 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4434,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:25.903676 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:26.038127 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.134s	user 0.107s	sys 0.027s 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":1040,"lbm_read_time_us":9387,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26278,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.038928 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:26.088251 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.049s	user 0.034s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17602,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:26.089005 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:26.100469 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.101028 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushMRSOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:26.144742 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushMRSOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.042s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1588,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1401,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:26.145623 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling LogGCOp(f0ade73b8c294c7f82a9f4b585445f83): free 112692317 bytes of WAL
I20260812 06:16:26.145948 23853 log_reader.cc:385] T f0ade73b8c294c7f82a9f4b585445f83: removed 11 log segments from log reader
I20260812 06:16:26.146026 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000014 (ops 65-69)
I20260812 06:16:26.146070 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000015 (ops 70-74)
I20260812 06:16:26.146102 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000016 (ops 75-79)
I20260812 06:16:26.146143 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000017 (ops 80-84)
I20260812 06:16:26.146178 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000018 (ops 85-89)
I20260812 06:16:26.146212 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000019 (ops 90-94)
I20260812 06:16:26.146237 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000020 (ops 95-99)
I20260812 06:16:26.146274 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000021 (ops 100-104)
I20260812 06:16:26.146313 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000022 (ops 105-109)
I20260812 06:16:26.146348 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000023 (ops 110-114)
I20260812 06:16:26.146382 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000024 (ops 115-119)
I20260812 06:16:26.178622 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: LogGCOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:16:26.179206 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling UndoDeltaBlockGCOp(f0ade73b8c294c7f82a9f4b585445f83): 447 bytes on disk
I20260812 06:16:26.179768 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: UndoDeltaBlockGCOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:16:26.180310 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:26.208505 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.028s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.209152 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:26.221524 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.012s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.222329 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:26.431838 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.209s	user 0.149s	sys 0.060s 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":1071,"lbm_read_time_us":15774,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36409,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":119296,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:16:26.432770 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=14.095187
I20260812 06:16:26.496513 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.064s	user 0.024s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26679,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.497148 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:26.508476 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.509045 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:26.690375 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.181s	user 0.133s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":798,"lbm_read_time_us":12036,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32141,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2500}
I20260812 06:16:26.691100 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=14.095187
I20260812 06:16:26.756126 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.065s	user 0.032s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23451,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:26.756774 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:26.768509 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4490,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.769106 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:26.954806 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.186s	user 0.118s	sys 0.067s 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":190,"lbm_read_time_us":14667,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33368,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:16:26.956184 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:26.990226 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.034s	user 0.008s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15708,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:26.990813 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:27.008282 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.013360 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:27.168191 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.155s	user 0.115s	sys 0.039s 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":962,"lbm_read_time_us":9647,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26210,"lbm_writes_lt_1ms":443,"mutex_wait_us":234,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:16:27.168857 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:27.216277 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.047s	user 0.029s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20957,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.216874 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:27.228358 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.229324 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:27.362993 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.133s	user 0.093s	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":200,"lbm_read_time_us":9321,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26543,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:16:27.363569 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:27.404526 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.041s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15760,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.405134 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:27.421053 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.421803 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:27.548887 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.127s	user 0.105s	sys 0.022s 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":487,"lbm_read_time_us":9369,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24332,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:16:27.549772 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:27.597844 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.048s	user 0.022s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18476,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.598694 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:27.610889 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.611404 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushMRSOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:27.652045 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushMRSOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.040s	user 0.039s	sys 0.000s Metrics: {"bytes_written":1152511,"cfile_init":1,"dirs.queue_time_us":194,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1581,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2238,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:27.652907 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling LogGCOp(f0ade73b8c294c7f82a9f4b585445f83): free 111786507 bytes of WAL
I20260812 06:16:27.653146 23853 log_reader.cc:385] T f0ade73b8c294c7f82a9f4b585445f83: removed 11 log segments from log reader
I20260812 06:16:27.653189 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000025 (ops 120-124)
I20260812 06:16:27.653218 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000026 (ops 125-129)
I20260812 06:16:27.653283 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000027 (ops 130-134)
I20260812 06:16:27.653316 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000028 (ops 135-139)
I20260812 06:16:27.653352 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000029 (ops 140-144)
I20260812 06:16:27.653383 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000030 (ops 145-148)
I20260812 06:16:27.653417 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000031 (ops 149-153)
I20260812 06:16:27.653460 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000032 (ops 154-158)
I20260812 06:16:27.653499 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000033 (ops 159-163)
I20260812 06:16:27.653538 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000034 (ops 164-168)
I20260812 06:16:27.653577 23853 log.cc:1079] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/f0ade73b8c294c7f82a9f4b585445f83/wal-000000035 (ops 169-172)
I20260812 06:16:27.679356 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: LogGCOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:27.679869 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:27.694429 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4184708,"delete_count":0,"lbm_write_time_us":4784,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:16:27.694892 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:27.706010 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4020608,"delete_count":0,"lbm_write_time_us":4197,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:16:27.706722 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:27.917476 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.211s	user 0.150s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795406,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1379,"lbm_read_time_us":13484,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35064,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21248,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:16:27.918373 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=14.095187
I20260812 06:16:27.970633 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.052s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23033,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.971160 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:28.126377 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.155s	user 0.119s	sys 0.022s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590227,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":253,"lbm_read_time_us":10437,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23404,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.127156 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling UndoDeltaBlockGCOp(f0ade73b8c294c7f82a9f4b585445f83): 447 bytes on disk
I20260812 06:16:28.127740 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: UndoDeltaBlockGCOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:16:28.128684 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=14.095187
I20260812 06:16:28.176151 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.047s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19627,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.176788 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=2.188937
I20260812 06:16:28.190507 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.191110 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=1.000000
I20260812 06:16:28.332480 23731 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.308s	user 1.916s	sys 0.201s
I20260812 06:16:28.371536 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: MajorDeltaCompactionOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.180s	user 0.129s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11823,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30323,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:28.372056 23926 maintenance_manager.cc:419] P ab5fde3cfb5c4cc493f60097ef4e7967: Scheduling FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83): perf score=10.126437
I20260812 06:16:28.394173 23731 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.061s	user 0.004s	sys 0.000s
I20260812 06:16:28.394992 23731 tablet_server.cc:179] TabletServer@127.23.44.193:0 shutting down...
I20260812 06:16:28.407543 23853 maintenance_manager.cc:643] P ab5fde3cfb5c4cc493f60097ef4e7967: FlushDeltaMemStoresOp(f0ade73b8c294c7f82a9f4b585445f83) complete. Timing: real 0.035s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15938,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:28.409638 23731 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:28.410015 23731 tablet_replica.cc:333] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967: stopping tablet replica
I20260812 06:16:28.410295 23731 raft_consensus.cc:2243] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:28.410542 23731 raft_consensus.cc:2272] T f0ade73b8c294c7f82a9f4b585445f83 P ab5fde3cfb5c4cc493f60097ef4e7967 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:28.426594 23731 tablet_server.cc:196] TabletServer@127.23.44.193:0 shutdown complete.
I20260812 06:16:28.431792 23731 master.cc:562] Master@127.23.44.254:42643 shutting down...
I20260812 06:16:28.435541 23731 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:28.435766 23731 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:28.435861 23731 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4d5a4ff412254c8d8e570fb4561b42ba: stopping tablet replica
I20260812 06:16:28.448401 23731 master.cc:584] Master@127.23.44.254:42643 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5869 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:28.562073 23731 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.44.254:44417
I20260812 06:16:28.562543 23731 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:28.565467 23731 server_base.cc:1061] running on GCE node
W20260812 06:16:28.565565 23970 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.565552 23968 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.565722 23967 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:28.566002 23731 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:28.566051 23731 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:28.566066 23731 hybrid_clock.cc:648] HybridClock initialized: now 1786515388566066 us; error 0 us; skew 500 ppm
I20260812 06:16:28.566973 23731 webserver.cc:533] Webserver started at http://127.23.44.254:40913/ using document root <none> and password file <none>
I20260812 06:16:28.567174 23731 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:28.567256 23731 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:28.567345 23731 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:28.567795 23731 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/master-0-root/instance:
uuid: "00076342917c4ce2817cefb26135943a"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-65mx"
I20260812 06:16:28.569551 23731 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:28.570605 23977 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.570885 23731 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:28.570953 23731 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/master-0-root
uuid: "00076342917c4ce2817cefb26135943a"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-65mx"
I20260812 06:16:28.571014 23731 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:28.596071 23731 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:28.596542 23731 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:28.600971 23731 rpc_server.cc:307] RPC server started. Bound to: 127.23.44.254:44417
I20260812 06:16:28.605659 24037 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.44.254:44417 every 8 connection(s)
I20260812 06:16:28.606262 24038 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:28.608099 24038 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a: Bootstrap starting.
I20260812 06:16:28.608927 24038 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:28.610116 24038 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a: No bootstrap required, opened a new log
I20260812 06:16:28.610581 24038 raft_consensus.cc:359] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00076342917c4ce2817cefb26135943a" member_type: VOTER }
I20260812 06:16:28.610692 24038 raft_consensus.cc:385] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:28.610740 24038 raft_consensus.cc:740] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 00076342917c4ce2817cefb26135943a, State: Initialized, Role: FOLLOWER
I20260812 06:16:28.610908 24038 consensus_queue.cc:260] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [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: "00076342917c4ce2817cefb26135943a" member_type: VOTER }
I20260812 06:16:28.611013 24038 raft_consensus.cc:399] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:28.611065 24038 raft_consensus.cc:493] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:28.611122 24038 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:28.611852 24038 raft_consensus.cc:515] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00076342917c4ce2817cefb26135943a" member_type: VOTER }
I20260812 06:16:28.612020 24038 leader_election.cc:304] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [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: 00076342917c4ce2817cefb26135943a; no voters: 
I20260812 06:16:28.612244 24038 leader_election.cc:290] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:28.612445 24041 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:28.612772 24041 raft_consensus.cc:697] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 1 LEADER]: Becoming Leader. State: Replica: 00076342917c4ce2817cefb26135943a, State: Running, Role: LEADER
I20260812 06:16:28.612869 24038 sys_catalog.cc:565] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:28.612932 24041 consensus_queue.cc:237] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [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: "00076342917c4ce2817cefb26135943a" member_type: VOTER }
I20260812 06:16:28.613459 24042 sys_catalog.cc:455] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "00076342917c4ce2817cefb26135943a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00076342917c4ce2817cefb26135943a" member_type: VOTER } }
I20260812 06:16:28.613576 24043 sys_catalog.cc:455] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 00076342917c4ce2817cefb26135943a. Latest consensus state: current_term: 1 leader_uuid: "00076342917c4ce2817cefb26135943a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00076342917c4ce2817cefb26135943a" member_type: VOTER } }
I20260812 06:16:28.613703 24043 sys_catalog.cc:458] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:28.613634 24042 sys_catalog.cc:458] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:28.614394 24055 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:28.615137 24055 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:28.615362 23731 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:28.617105 24055 catalog_manager.cc:1383] Generated new cluster ID: 6d60f96e7e8e48b8a1b202dada1a6f0e
I20260812 06:16:28.617172 24055 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:28.625787 24055 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:28.626386 24055 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:28.631165 24055 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a: Generated new TSK 0
I20260812 06:16:28.631410 24055 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:28.648168 23731 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:28.650313 24066 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.650367 24068 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.650378 24065 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:28.650897 23731 server_base.cc:1061] running on GCE node
I20260812 06:16:28.651137 23731 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:28.651180 23731 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:28.651196 23731 hybrid_clock.cc:648] HybridClock initialized: now 1786515388651196 us; error 0 us; skew 500 ppm
I20260812 06:16:28.652100 23731 webserver.cc:533] Webserver started at http://127.23.44.193:33475/ using document root <none> and password file <none>
I20260812 06:16:28.652325 23731 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:28.652382 23731 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:28.652486 23731 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:28.652952 23731 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/instance:
uuid: "aa493eabd8214bb1b7ea4f47e003d98f"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-65mx"
I20260812 06:16:28.654547 23731 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:28.655670 24075 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.656069 23731 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:28.656265 23731 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root
uuid: "aa493eabd8214bb1b7ea4f47e003d98f"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-65mx"
I20260812 06:16:28.656383 23731 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:28.677275 23731 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:28.677786 23731 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:28.678153 23731 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:28.678678 23731 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:28.678740 23731 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.678794 23731 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:28.678841 23731 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.684273 23731 rpc_server.cc:307] RPC server started. Bound to: 127.23.44.193:42849
I20260812 06:16:28.684288 24152 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.44.193:42849 every 8 connection(s)
I20260812 06:16:28.693511 24154 heartbeater.cc:344] Connected to a master server at 127.23.44.254:44417
I20260812 06:16:28.693648 24154 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:28.693915 24154 heartbeater.cc:507] Master 127.23.44.254:44417 requested a full tablet report, sending...
I20260812 06:16:28.694590 23995 ts_manager.cc:194] Registered new tserver with Master: aa493eabd8214bb1b7ea4f47e003d98f (127.23.44.193:42849)
I20260812 06:16:28.694849 23731 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010042026s
I20260812 06:16:28.695523 23995 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44986
I20260812 06:16:28.703445 23995 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44992:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:28.712889 24108 tablet_service.cc:1511] Processing CreateTablet for tablet ecbf176d722d46899a38112a5aeeb2e6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f875befc8e584b6f889f88e122703797]), partition=
I20260812 06:16:28.713231 24108 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ecbf176d722d46899a38112a5aeeb2e6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:28.715812 24169 tablet_bootstrap.cc:492] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Bootstrap starting.
I20260812 06:16:28.716675 24169 tablet_bootstrap.cc:654] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:28.717778 24169 tablet_bootstrap.cc:492] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: No bootstrap required, opened a new log
I20260812 06:16:28.717913 24169 ts_tablet_manager.cc:1403] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:16:28.718515 24169 raft_consensus.cc:359] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa493eabd8214bb1b7ea4f47e003d98f" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 42849 } }
I20260812 06:16:28.718674 24169 raft_consensus.cc:385] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:28.718726 24169 raft_consensus.cc:740] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: aa493eabd8214bb1b7ea4f47e003d98f, State: Initialized, Role: FOLLOWER
I20260812 06:16:28.718891 24169 consensus_queue.cc:260] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [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: "aa493eabd8214bb1b7ea4f47e003d98f" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 42849 } }
I20260812 06:16:28.718966 24169 raft_consensus.cc:399] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:28.719027 24169 raft_consensus.cc:493] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:28.719089 24169 raft_consensus.cc:3060] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:28.719826 24169 raft_consensus.cc:515] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa493eabd8214bb1b7ea4f47e003d98f" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 42849 } }
I20260812 06:16:28.719949 24169 leader_election.cc:304] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [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: aa493eabd8214bb1b7ea4f47e003d98f; no voters: 
I20260812 06:16:28.720209 24169 leader_election.cc:290] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:28.720389 24171 raft_consensus.cc:2804] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:28.720575 24171 raft_consensus.cc:697] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 1 LEADER]: Becoming Leader. State: Replica: aa493eabd8214bb1b7ea4f47e003d98f, State: Running, Role: LEADER
I20260812 06:16:28.720640 24154 heartbeater.cc:499] Master 127.23.44.254:44417 was elected leader, sending a full tablet report...
I20260812 06:16:28.720580 24169 ts_tablet_manager.cc:1434] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:28.720758 24171 consensus_queue.cc:237] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [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: "aa493eabd8214bb1b7ea4f47e003d98f" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 42849 } }
I20260812 06:16:28.722289 23995 catalog_manager.cc:5719] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f reported cstate change: term changed from 0 to 1, leader changed from <none> to aa493eabd8214bb1b7ea4f47e003d98f (127.23.44.193). New cstate: current_term: 1 leader_uuid: "aa493eabd8214bb1b7ea4f47e003d98f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa493eabd8214bb1b7ea4f47e003d98f" member_type: VOTER last_known_addr { host: "127.23.44.193" port: 42849 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:28.782886 23731 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.015s	sys 0.008s
I20260812 06:16:28.935340 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushMRSOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=19.054940
I20260812 06:16:29.116823 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushMRSOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.181s	user 0.126s	sys 0.055s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1045,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46929,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:29.117651 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling LogGCOp(ecbf176d722d46899a38112a5aeeb2e6): free 20743831 bytes of WAL
I20260812 06:16:29.117899 24081 log_reader.cc:385] T ecbf176d722d46899a38112a5aeeb2e6: removed 2 log segments from log reader
I20260812 06:16:29.117946 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000001 (ops 1-6)
I20260812 06:16:29.117978 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000002 (ops 7-11)
I20260812 06:16:29.122502 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: LogGCOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:29.122917 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling UndoDeltaBlockGCOp(ecbf176d722d46899a38112a5aeeb2e6): 16411397 bytes on disk
I20260812 06:16:29.123381 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: UndoDeltaBlockGCOp(ecbf176d722d46899a38112a5aeeb2e6) 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:16:29.123824 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:29.136327 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4429,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.136893 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:29.308903 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.172s	user 0.109s	sys 0.062s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":459,"lbm_read_time_us":12979,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27167,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":357,"threads_started":5,"update_count":2000}
I20260812 06:16:29.309703 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:29.344234 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.034s	user 0.013s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15134,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.344805 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:29.360522 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.361109 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:29.491858 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.131s	user 0.089s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":701,"lbm_read_time_us":7942,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27003,"lbm_writes_lt_1ms":443,"mutex_wait_us":239,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:16:29.492655 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:29.544221 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.051s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17750,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.544772 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:29.556195 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.556756 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:29.691588 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.135s	user 0.102s	sys 0.033s 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":337,"lbm_read_time_us":10650,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25227,"lbm_writes_lt_1ms":443,"mutex_wait_us":98,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:16:29.692279 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:29.735082 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.043s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17047,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.735666 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:29.747586 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4259,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.748214 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:29.877825 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.129s	user 0.110s	sys 0.019s 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":870,"lbm_read_time_us":8145,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27783,"lbm_writes_lt_1ms":443,"mutex_wait_us":464,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:29.878495 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:29.935199 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.057s	user 0.015s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18147,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.935802 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:29.946786 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4338,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.947290 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:30.106976 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.160s	user 0.103s	sys 0.056s 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":869,"lbm_read_time_us":12550,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25545,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:16:30.107589 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:30.154691 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.047s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15023,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.155251 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:30.167480 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.012s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4453,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.168177 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:30.294442 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.126s	user 0.090s	sys 0.036s 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":233,"lbm_read_time_us":10086,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23834,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:16:30.295183 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:30.338205 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.043s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17493,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.338835 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:30.350001 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.350798 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushMRSOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:30.379074 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushMRSOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1858,"drs_written":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1630,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:30.379722 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling LogGCOp(ecbf176d722d46899a38112a5aeeb2e6): free 112239308 bytes of WAL
I20260812 06:16:30.379999 24081 log_reader.cc:385] T ecbf176d722d46899a38112a5aeeb2e6: removed 11 log segments from log reader
I20260812 06:16:30.380056 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000003 (ops 12-16)
I20260812 06:16:30.380086 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000004 (ops 17-21)
I20260812 06:16:30.380142 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000005 (ops 22-26)
I20260812 06:16:30.380189 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000006 (ops 27-31)
I20260812 06:16:30.380208 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000007 (ops 32-36)
I20260812 06:16:30.380263 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000008 (ops 37-41)
I20260812 06:16:30.380304 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000009 (ops 42-46)
I20260812 06:16:30.380347 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000010 (ops 47-50)
I20260812 06:16:30.380393 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000011 (ops 51-55)
I20260812 06:16:30.380436 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000012 (ops 56-60)
I20260812 06:16:30.380475 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000013 (ops 61-65)
I20260812 06:16:30.407096 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: LogGCOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.027s	user 0.002s	sys 0.022s Metrics: {}
I20260812 06:16:30.407564 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling UndoDeltaBlockGCOp(ecbf176d722d46899a38112a5aeeb2e6): 447 bytes on disk
I20260812 06:16:30.408186 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: UndoDeltaBlockGCOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:16:30.408789 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=3.181125
I20260812 06:16:30.422210 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5341,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:30.422710 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:30.434913 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4000,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:30.435961 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:30.613737 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.178s	user 0.122s	sys 0.055s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":624,"lbm_read_time_us":12748,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35259,"lbm_writes_lt_1ms":643,"mutex_wait_us":312,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19968,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:16:30.614969 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=14.095187
I20260812 06:16:30.672159 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.057s	user 0.041s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24763,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.672986 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:30.692926 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.020s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7638,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.693517 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:30.862900 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.169s	user 0.126s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1255,"lbm_read_time_us":12321,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29273,"lbm_writes_lt_1ms":543,"mutex_wait_us":353,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:16:30.863534 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=14.095187
I20260812 06:16:30.910087 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.046s	user 0.016s	sys 0.027s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21383,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.910557 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:31.075954 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.165s	user 0.117s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672161,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1852,"lbm_read_time_us":12212,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26620,"lbm_writes_lt_1ms":443,"mutex_wait_us":605,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:16:31.077133 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=11.118625
I20260812 06:16:31.109591 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12594659,"delete_count":0,"lbm_write_time_us":13979,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1535}
I20260812 06:16:31.110324 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:31.125147 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5746,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:16:31.125595 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:31.263991 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.138s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1071,"lbm_read_time_us":9812,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26182,"lbm_writes_lt_1ms":443,"mutex_wait_us":284,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2000}
I20260812 06:16:31.264730 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:31.313616 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.049s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14094,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.314218 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:31.326929 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.327521 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:31.468855 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.141s	user 0.112s	sys 0.028s 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":180,"lbm_read_time_us":10176,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28512,"lbm_writes_lt_1ms":443,"mutex_wait_us":5,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:16:31.469477 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:31.512076 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.042s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17505,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.512693 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:31.526094 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.013s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.526822 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:31.654062 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.127s	user 0.110s	sys 0.016s 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":332,"lbm_read_time_us":8084,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25658,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:16:31.654768 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:31.718526 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.064s	user 0.038s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24504,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.719137 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:31.730041 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.730643 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:31.893326 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.162s	user 0.115s	sys 0.047s 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":589,"lbm_read_time_us":12074,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24974,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:16:31.893851 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:31.943468 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.049s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":19329,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.944180 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:31.959702 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.960217 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushMRSOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:31.992921 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushMRSOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1500,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2256,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:31.993582 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling LogGCOp(ecbf176d722d46899a38112a5aeeb2e6): free 133024426 bytes of WAL
I20260812 06:16:31.993829 24081 log_reader.cc:385] T ecbf176d722d46899a38112a5aeeb2e6: removed 13 log segments from log reader
I20260812 06:16:31.993875 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000014 (ops 66-70)
I20260812 06:16:31.993906 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000015 (ops 71-75)
I20260812 06:16:31.993970 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000016 (ops 76-80)
I20260812 06:16:31.994016 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000017 (ops 81-85)
I20260812 06:16:31.994060 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000018 (ops 86-90)
I20260812 06:16:31.994119 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000019 (ops 91-94)
I20260812 06:16:31.994169 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000020 (ops 95-99)
I20260812 06:16:31.994226 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000021 (ops 100-104)
I20260812 06:16:31.994267 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000022 (ops 105-109)
I20260812 06:16:31.994308 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000023 (ops 110-114)
I20260812 06:16:31.994349 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000024 (ops 115-119)
I20260812 06:16:31.994393 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000025 (ops 120-124)
I20260812 06:16:31.994434 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000026 (ops 125-129)
I20260812 06:16:32.024585 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: LogGCOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.031s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:32.025038 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=3.181125
I20260812 06:16:32.050313 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.025s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4495,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:32.051014 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:32.066670 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.015s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5782,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:32.067368 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:32.280777 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.213s	user 0.170s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1028,"lbm_read_time_us":15387,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34759,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:16:32.281978 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=14.095187
I20260812 06:16:32.350186 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.068s	user 0.019s	sys 0.047s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22881,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.351063 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:32.364388 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.364929 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:32.572988 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.208s	user 0.153s	sys 0.045s 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":1270,"lbm_read_time_us":15610,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33319,"lbm_writes_lt_1ms":543,"mutex_wait_us":278,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:16:32.573832 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling UndoDeltaBlockGCOp(ecbf176d722d46899a38112a5aeeb2e6): 483 bytes on disk
I20260812 06:16:32.574420 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: UndoDeltaBlockGCOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:16:32.575014 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=14.095187
I20260812 06:16:32.627398 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.052s	user 0.020s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22991,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.628115 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:32.655336 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.027s	user 0.013s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.655917 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:32.851024 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.195s	user 0.118s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":13542,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31602,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:16:32.851811 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=14.095187
I20260812 06:16:32.908197 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.056s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21371,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.908866 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:32.921758 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.922410 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:33.118346 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.196s	user 0.139s	sys 0.044s 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":527,"lbm_read_time_us":12187,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32492,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:16:33.119146 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=11.118625
I20260812 06:16:33.158798 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.039s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16211,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:33.159333 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:33.182267 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.023s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.182873 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:33.194758 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3951,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:33.195356 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:33.356993 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.161s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":929,"lbm_read_time_us":12023,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31027,"lbm_writes_lt_1ms":543,"mutex_wait_us":345,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:16:33.357787 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:33.405929 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.048s	user 0.025s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22773,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:33.406679 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:33.422808 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.423521 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:33.558791 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.135s	user 0.107s	sys 0.028s 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":527,"lbm_read_time_us":9709,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25422,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":77824,"update_count":2000}
I20260812 06:16:33.559463 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=10.126437
I20260812 06:16:33.608886 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.049s	user 0.034s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17778,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:33.609593 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:33.623406 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4648,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.624107 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushMRSOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:33.661332 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushMRSOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.037s	user 0.032s	sys 0.005s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":1547,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1669,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:33.662128 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling LogGCOp(ecbf176d722d46899a38112a5aeeb2e6): free 124710562 bytes of WAL
I20260812 06:16:33.662371 24081 log_reader.cc:385] T ecbf176d722d46899a38112a5aeeb2e6: removed 12 log segments from log reader
I20260812 06:16:33.662416 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000027 (ops 130-134)
I20260812 06:16:33.662446 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000028 (ops 135-139)
I20260812 06:16:33.662626 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000029 (ops 140-144)
I20260812 06:16:33.662701 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000030 (ops 145-149)
I20260812 06:16:33.662722 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000031 (ops 150-154)
I20260812 06:16:33.662741 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000032 (ops 155-159)
I20260812 06:16:33.662802 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000033 (ops 160-164)
I20260812 06:16:33.662846 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000034 (ops 165-169)
I20260812 06:16:33.662878 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000035 (ops 170-174)
I20260812 06:16:33.662919 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000036 (ops 175-179)
I20260812 06:16:33.662961 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000037 (ops 180-184)
I20260812 06:16:33.663002 24081 log.cc:1079] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: Deleting log segment in path: /tmp/dist-test-taski6wHiM/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382668663-23731-0/minicluster-data/ts-0-root/wals/ecbf176d722d46899a38112a5aeeb2e6/wal-000000038 (ops 185-189)
I20260812 06:16:33.693392 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: LogGCOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:33.693948 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling UndoDeltaBlockGCOp(ecbf176d722d46899a38112a5aeeb2e6): 472 bytes on disk
I20260812 06:16:33.694568 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: UndoDeltaBlockGCOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:16:33.695439 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=6.157687
I20260812 06:16:33.726270 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.031s	user 0.012s	sys 0.017s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13463,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:33.726807 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:33.913311 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.186s	user 0.128s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":6509,"lbm_read_time_us":12304,"lbm_reads_lt_1ms":665,"lbm_write_time_us":38771,"lbm_writes_lt_1ms":643,"mutex_wait_us":2950,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9728,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:16:33.913971 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=14.095187
I20260812 06:16:33.968782 23731 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.186s	user 1.940s	sys 0.168s
I20260812 06:16:33.971885 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.058s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24728,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.972357 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=2.188937
I20260812 06:16:33.983749 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: FlushDeltaMemStoresOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":500}
I20260812 06:16:33.984294 24156 maintenance_manager.cc:419] P aa493eabd8214bb1b7ea4f47e003d98f: Scheduling MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6): perf score=1.000000
I20260812 06:16:34.018410 23731 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.049s	user 0.003s	sys 0.000s
I20260812 06:16:34.019263 23731 tablet_server.cc:179] TabletServer@127.23.44.193:0 shutting down...
I20260812 06:16:34.104187 24081 maintenance_manager.cc:643] P aa493eabd8214bb1b7ea4f47e003d98f: MajorDeltaCompactionOp(ecbf176d722d46899a38112a5aeeb2e6) complete. Timing: real 0.119s	user 0.087s	sys 0.032s Metrics: {"cfile_cache_hit":392,"cfile_cache_hit_bytes":16040670,"cfile_cache_miss":140,"cfile_cache_miss_bytes":8734019,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":895,"lbm_read_time_us":3721,"lbm_reads_lt_1ms":172,"lbm_write_time_us":27777,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:16:34.104933 23731 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:34.105173 23731 tablet_replica.cc:333] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f: stopping tablet replica
I20260812 06:16:34.105356 23731 raft_consensus.cc:2243] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.105553 23731 raft_consensus.cc:2272] T ecbf176d722d46899a38112a5aeeb2e6 P aa493eabd8214bb1b7ea4f47e003d98f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.110486 23731 tablet_server.cc:196] TabletServer@127.23.44.193:0 shutdown complete.
I20260812 06:16:34.152320 23731 master.cc:562] Master@127.23.44.254:44417 shutting down...
I20260812 06:16:34.156477 23731 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.156730 23731 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.156792 23731 tablet_replica.cc:333] T 00000000000000000000000000000000 P 00076342917c4ce2817cefb26135943a: stopping tablet replica
I20260812 06:16:34.169637 23731 master.cc:584] Master@127.23.44.254:44417 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5751 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11621 ms total)

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