log spamming on [ble/block_based/block_based_table_reader.cc:852] Tail prefetch size 524288 is calculated based on TailPrefetchStats

[dfa1]

Note: Please use Issues only for bug reports. For questions, discussions, feature requests, etc. post to dev group: https://groups.google.com/forum/#!forum/rocksdb or https://www.facebook.com/groups/rocksdb.dev

Expected behavior

To not receive these logs (or to know what to do, like documentation).

Actual behavior

Many logs per second

Steps to reproduce the behavior

I'm not able to reproduce it locally (windows 11) but this appears often in our Linux servers. It is happening since the upgrade to rocksdbjni 8.x.

This is the OPTIONS file:

# This is a RocksDB option file.
#
# For detailed file format spec, please refer to the example file
# in examples/rocksdb_option_file_example.ini
#

[Version]
  rocksdb_version=8.6.7
  options_file_version=1.1

[DBOptions]
  max_background_flushes=-1
  compaction_readahead_size=2097152
  wal_bytes_per_sync=0
  bytes_per_sync=0
  max_open_files=250
  stats_history_buffer_size=1048576
  stats_dump_period_sec=600
  stats_persist_period_sec=600
  delete_obsolete_files_period_micros=21600000000
  max_total_wal_size=0
  strict_bytes_per_sync=false
  delayed_write_rate=16777216
  avoid_flush_during_shutdown=false
  writable_file_max_buffer_size=1048576
  max_subcompactions=1
  max_background_compactions=-1
  max_background_jobs=6
  lowest_used_cache_tier=kNonVolatileBlockTier
  bgerror_resume_retry_interval=1000000
  max_bgerror_resume_count=2147483647
  best_efforts_recovery=false
  write_dbid_to_manifest=false
  avoid_unnecessary_blocking_io=false
  atomic_flush=false
  log_readahead_size=0
  dump_malloc_stats=false
  info_log_level=INFO_LEVEL
  write_thread_max_yield_usec=100
  max_write_batch_group_size_bytes=1048576
  wal_compression=kNoCompression
  write_thread_slow_yield_usec=3
  enable_pipelined_write=false
  persist_stats_to_disk=false
  max_manifest_file_size=1073741824
  WAL_size_limit_MB=0
  fail_if_options_file_error=false
  max_log_file_size=0
  manifest_preallocation_size=4194304
  log_file_time_to_roll=0
  allow_data_in_errors=false
  WAL_ttl_seconds=0
  recycle_log_file_num=0
  file_checksum_gen_factory=nullptr
  keep_log_file_num=1000
  db_write_buffer_size=0
  table_cache_numshardbits=6
  use_adaptive_mutex=false
  allow_ingest_behind=false
  skip_checking_sst_file_sizes_on_db_open=false
  random_access_max_buffer_size=1048576
  access_hint_on_compaction_start=NORMAL
  allow_concurrent_memtable_write=true
  track_and_verify_wals_in_manifest=false
  skip_stats_update_on_db_open=false
  compaction_verify_record_count=true
  paranoid_checks=true
  max_file_opening_threads=16
  verify_sst_unique_id_in_manifest=true
  avoid_flush_during_recovery=false
  flush_verify_memtable_count=true
  db_host_id=__hostname__
  error_if_exists=false
  wal_recovery_mode=kPointInTimeRecovery
  enable_thread_tracking=false
  is_fd_close_on_exec=true
  enforce_single_del_contracts=true
  create_missing_column_families=false
  create_if_missing=true
  use_fsync=false
  wal_filter=nullptr
  allow_2pc=false
  use_direct_io_for_flush_and_compaction=false
  manual_wal_flush=false
  enable_write_thread_adaptive_yield=true
  use_direct_reads=false
  allow_mmap_writes=false
  allow_fallocate=true
  two_write_queues=false
  allow_mmap_reads=false
  unordered_write=false
  advise_random_on_open=false
  

[CFOptions "default"]
  memtable_max_range_deletions=0
  block_protection_bytes_per_key=0
  memtable_protection_bytes_per_key=0
  sample_for_compression=0
  blob_file_starting_level=0
  blob_compaction_readahead_size=0
  blob_garbage_collection_force_threshold=1.000000
  enable_blob_garbage_collection=false
  min_blob_size=0
  last_level_temperature=kUnknown
  enable_blob_files=false
  target_file_size_base=68157440
  max_sequential_skip_in_iterations=8
  prepopulate_blob_cache=kDisable
  compaction_options_fifo={file_temperature_age_thresholds=;allow_compaction=false;age_for_warm=0;max_table_files_size=1073741824;}
  max_bytes_for_level_multiplier=10.000000
  max_bytes_for_level_multiplier_additional=1:1:1:1:1:1:1
  max_bytes_for_level_base=268435456
  experimental_mempurge_threshold=0.000000
  write_buffer_size=536870912
  bottommost_compression=kZSTD
  prefix_extractor=nullptr
  blob_file_size=268435456
  memtable_huge_page_size=0
  bottommost_file_compaction_delay=0
  max_successive_merges=0
  compression_opts={checksum=false;max_dict_buffer_bytes=0;enabled=false;max_dict_bytes=0;max_compressed_bytes_per_kb=896;parallel_threads=1;zstd_max_train_bytes=0;level=32767;use_zstd_dict_trainer=true;strategy=0;window_bits=-14;}
  arena_block_size=1048576
  memtable_whole_key_filtering=false
  target_file_size_multiplier=1
  max_write_buffer_number=2
  blob_compression_type=kNoCompression
  compression=kLZ4Compression
  level0_stop_writes_trigger=36
  level0_slowdown_writes_trigger=20
  level0_file_num_compaction_trigger=4
  ignore_max_compaction_bytes_for_input=true
  max_compaction_bytes=1703936000
  compaction_options_universal={allow_trivial_move=false;incremental=false;stop_style=kCompactionStopStyleTotalSize;compression_size_percent=-1;max_size_amplification_percent=200;max_merge_width=4294967295;min_merge_width=2;size_ratio=1;}
  memtable_prefix_bloom_size_ratio=0.000000
  hard_pending_compaction_bytes_limit=274877906944
  bottommost_compression_opts={checksum=false;max_dict_buffer_bytes=0;enabled=false;max_dict_bytes=0;max_compressed_bytes_per_kb=896;parallel_threads=1;zstd_max_train_bytes=0;level=32767;use_zstd_dict_trainer=true;strategy=0;window_bits=-14;}
  blob_garbage_collection_age_cutoff=0.250000
  ttl=2592000
  soft_pending_compaction_bytes_limit=68719476736
  inplace_update_num_locks=10000
  paranoid_file_checks=false
  check_flush_compaction_key_order=true
  periodic_compaction_seconds=0
  disable_auto_compactions=false
  report_bg_io_stats=false
  compaction_pri=kMinOverlappingRatio
  compaction_style=kCompactionStyleLevel
  merge_operator=nullptr
  table_factory=BlockBasedTable
  memtable_factory=SkipListFactory
  comparator=leveldb.BytewiseComparator
  compaction_filter_factory=nullptr
  num_levels=7
  min_write_buffer_number_to_merge=1
  bloom_locality=0
  max_write_buffer_size_to_maintain=0
  sst_partitioner_factory=nullptr
  preserve_internal_time_seconds=0
  preclude_last_level_data_seconds=0
  max_write_buffer_number_to_maintain=0
  default_temperature=kUnknown
  optimize_filters_for_hits=false
  level_compaction_dynamic_file_size=true
  memtable_insert_with_hint_prefix_extractor=nullptr
  level_compaction_dynamic_level_bytes=true
  inplace_update_support=false
  persist_user_defined_timestamps=true
  compaction_filter=nullptr
  force_consistency_checks=true
  
[TableOptions/BlockBasedTable "default"]
  num_file_reads_for_auto_readahead=2
  initial_auto_readahead_size=8192
  metadata_cache_options={unpartitioned_pinning=kFallback;partition_pinning=kFallback;top_level_index_pinning=kFallback;}
  enable_index_compression=true
  pin_top_level_index_and_filter=true
  read_amp_bytes_per_bit=0
  verify_compression=false
  prepopulate_block_cache=kDisable
  format_version=6
  partition_filters=false
  metadata_block_size=4096
  max_auto_readahead_size=262144
  index_block_restart_interval=1
  block_size_deviation=10
  block_size=16384
  detect_filter_construct_corruption=false
  no_block_cache=false
  checksum=kCRC32c
  filter_policy=nullptr
  data_block_hash_table_util_ratio=0.750000
  block_restart_interval=16
  index_type=kTwoLevelIndexSearch
  pin_l0_filter_and_index_blocks_in_cache=false
  data_block_index_type=kDataBlockBinaryAndHash
  cache_index_and_filter_blocks_with_high_priority=true
  whole_key_filtering=false
  index_shortening=kShortenSeparators
  cache_index_and_filter_blocks=false
  block_align=false
  optimize_filters_for_memory=false
  flush_block_policy_factory=FlushBlockBySizePolicyFactory

[andlr]

I am seeing the same in our envs since updating to 9.0.0.
It does spam quite a lot on environments with thousands of SST files, on each DB open.

It was introduced here #11406
It's not a problem, it's just some backward compatibility stuff:

For backward compatibility, we fall back to TailPrefetchStats and last to simple heuristics that the tail size is a linear portion of the file size - see PR conversation for more.

I was thinking of opening PR to suggest changing log level to INFO, so I'll do that

[ajkr]

or to know what to do, like documentation

You'll want to make sure your files are compacted by a new enough version before we delete the complicated original behavior as a fallback (TailPrefetchStats). Any version that spews the warning is new enough.

[dfa1]

@ajkr thanks!

I triggered a manual compaction via Java API:

  public void compactRange() throws RocksDBException {
    compactRange(null);
  }

but I still see a lot logs like that (RocksDB 8.11.4). Any idea why?

[andlr]

Because compactRange() without any options won't compact every single SST.

I think BottommostLevelCompaction::kForce option in CompactRangeOptions::bottommost_level_compaction should help. With this API:

  public void compactRange(
      /* @Nullable */ final ColumnFamilyHandle columnFamilyHandle,
      final byte[] begin, final byte[] end,
      final CompactRangeOptions compactRangeOptions) throws RocksDBException {
    compactRange(nativeHandle_,
        begin, begin == null ? -1 : begin.length,
        end, end == null ? -1 : end.length,
        compactRangeOptions.nativeHandle_,
        columnFamilyHandle == null ? 0 : columnFamilyHandle.nativeHandle_);
  }

[dfa1]

problem has been fixed by using compactRange() with bottommost_level_compaction

thanks @ajkr @andlr!