Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

infinite compaction loop #10752

Closed
andoryu- opened this issue Sep 28, 2022 · 5 comments
Closed

infinite compaction loop #10752

andoryu- opened this issue Sep 28, 2022 · 5 comments
Assignees
@cbi42
Labels
compaction

Comments

@andoryu-
Copy link

andoryu- commented Sep 28, 2022 •
edited
Loading

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

rocksdb do necessary compactions instead of being locked in a compaction loop.

Actual behavior

rocksdb won't stop compacting, it just keep compacting the same file from L1 to L1, with BottommostFiles as reason.
lsm_state stays [0, 1, 0, 0, 0, 0, 0] but the same file is compacted over and over.

Steps to reproduce the behavior

start with two column families.
write to the other cf(not default) with udt enabled.
then rocksdb starts to keep compacting L1 to L1.

info log see below:


2022/09/28-17:19:20.082149 139935010756352 RocksDB version: 7.5.3
2022/09/28-17:19:20.082227 139935010756352 Git sha 540d5aae516265170564ec27b3e67a54a11b7045
2022/09/28-17:19:20.082234 139935010756352 Compile date 2022-09-20 02:42:19
2022/09/28-17:19:20.082238 139935010756352 DB SUMMARY
2022/09/28-17:19:20.082241 139935010756352 DB Session ID:  66QZSRNEIIZAMC6PP0QG
2022/09/28-17:19:20.082245 139935010756352 CURRENT file:  CURRENT
2022/09/28-17:19:20.082248 139935010756352 IDENTITY file:  IDENTITY
2022/09/28-17:19:20.082252 139935010756352 MANIFEST file:  MANIFEST-1424571 size: 4720261 Bytes
2022/09/28-17:19:20.082255 139935010756352 SST files in ./data/store0/3/0/db dir, Total Num: 4, files: 1424568.sst 1424569.sst 1448769.sst 1448770.sst 
2022/09/28-17:19:20.082259 139935010756352 Write Ahead Log file in ./data/store0/3/0/db: 1424570.log size: 2746 ; 
2022/09/28-17:19:20.082263 139935010756352                         Options.error_if_exists: 0
2022/09/28-17:19:20.082266 139935010756352                       Options.create_if_missing: 1
2022/09/28-17:19:20.082269 139935010756352                         Options.paranoid_checks: 0
2022/09/28-17:19:20.082273 139935010756352             Options.flush_verify_memtable_count: 1
2022/09/28-17:19:20.082276 139935010756352                               Options.track_and_verify_wals_in_manifest: 0
2022/09/28-17:19:20.082279 139935010756352        Options.verify_sst_unique_id_in_manifest: 0
2022/09/28-17:19:20.082283 139935010756352                                     Options.env: 0x1e8a340
2022/09/28-17:19:20.082286 139935010756352                                      Options.fs: PosixFileSystem
2022/09/28-17:19:20.082289 139935010756352                                Options.info_log: 0x615000044000
2022/09/28-17:19:20.082293 139935010756352                Options.max_file_opening_threads: 16
2022/09/28-17:19:20.082296 139935010756352                              Options.statistics: (nil)
2022/09/28-17:19:20.082299 139935010756352                               Options.use_fsync: 0
2022/09/28-17:19:20.082302 139935010756352                       Options.max_log_file_size: 1048576
2022/09/28-17:19:20.082305 139935010756352                  Options.max_manifest_file_size: 8388608
2022/09/28-17:19:20.082308 139935010756352                   Options.log_file_time_to_roll: 0
2022/09/28-17:19:20.082311 139935010756352                       Options.keep_log_file_num: 2
2022/09/28-17:19:20.082314 139935010756352                    Options.recycle_log_file_num: 0
2022/09/28-17:19:20.082317 139935010756352                         Options.allow_fallocate: 1
2022/09/28-17:19:20.082321 139935010756352                        Options.allow_mmap_reads: 0
2022/09/28-17:19:20.082324 139935010756352                       Options.allow_mmap_writes: 0
2022/09/28-17:19:20.082327 139935010756352                        Options.use_direct_reads: 0
2022/09/28-17:19:20.082330 139935010756352                        Options.use_direct_io_for_flush_and_compaction: 0
2022/09/28-17:19:20.082333 139935010756352          Options.create_missing_column_families: 1
2022/09/28-17:19:20.082336 139935010756352                              Options.db_log_dir: 
2022/09/28-17:19:20.082339 139935010756352                                 Options.wal_dir: 
2022/09/28-17:19:20.082343 139935010756352                Options.table_cache_numshardbits: 6
2022/09/28-17:19:20.082346 139935010756352                         Options.WAL_ttl_seconds: 0
2022/09/28-17:19:20.082349 139935010756352                       Options.WAL_size_limit_MB: 0
2022/09/28-17:19:20.082352 139935010756352                        Options.max_write_batch_group_size_bytes: 1048576
2022/09/28-17:19:20.082355 139935010756352             Options.manifest_preallocation_size: 4194304
2022/09/28-17:19:20.082358 139935010756352                     Options.is_fd_close_on_exec: 1
2022/09/28-17:19:20.082361 139935010756352                   Options.advise_random_on_open: 1
2022/09/28-17:19:20.082365 139935010756352                    Options.db_write_buffer_size: 0
2022/09/28-17:19:20.082368 139935010756352                    Options.write_buffer_manager: 0x60e000044600
2022/09/28-17:19:20.082377 139935010756352         Options.access_hint_on_compaction_start: 1
2022/09/28-17:19:20.082380 139935010756352           Options.random_access_max_buffer_size: 1048576
2022/09/28-17:19:20.082384 139935010756352                      Options.use_adaptive_mutex: 0
2022/09/28-17:19:20.082387 139935010756352                            Options.rate_limiter: (nil)
2022/09/28-17:19:20.082390 139935010756352     Options.sst_file_manager.rate_bytes_per_sec: 0
2022/09/28-17:19:20.082393 139935010756352                       Options.wal_recovery_mode: 2
2022/09/28-17:19:20.082396 139935010756352                  Options.enable_thread_tracking: 0
2022/09/28-17:19:20.082400 139935010756352                  Options.enable_pipelined_write: 0
2022/09/28-17:19:20.082403 139935010756352                  Options.unordered_write: 0
2022/09/28-17:19:20.082406 139935010756352         Options.allow_concurrent_memtable_write: 1
2022/09/28-17:19:20.082409 139935010756352      Options.enable_write_thread_adaptive_yield: 1
2022/09/28-17:19:20.082412 139935010756352             Options.write_thread_max_yield_usec: 100
2022/09/28-17:19:20.082415 139935010756352            Options.write_thread_slow_yield_usec: 3
2022/09/28-17:19:20.082419 139935010756352                               Options.row_cache: None
2022/09/28-17:19:20.082422 139935010756352                              Options.wal_filter: None
2022/09/28-17:19:20.082425 139935010756352             Options.avoid_flush_during_recovery: 0
2022/09/28-17:19:20.082428 139935010756352             Options.allow_ingest_behind: 1
2022/09/28-17:19:20.082431 139935010756352             Options.two_write_queues: 0
2022/09/28-17:19:20.082434 139935010756352             Options.manual_wal_flush: 0
2022/09/28-17:19:20.082437 139935010756352             Options.wal_compression: 0
2022/09/28-17:19:20.082440 139935010756352             Options.atomic_flush: 0
2022/09/28-17:19:20.082443 139935010756352             Options.avoid_unnecessary_blocking_io: 0
2022/09/28-17:19:20.082447 139935010756352                 Options.persist_stats_to_disk: 0
2022/09/28-17:19:20.082450 139935010756352                 Options.write_dbid_to_manifest: 0
2022/09/28-17:19:20.082453 139935010756352                 Options.log_readahead_size: 0
2022/09/28-17:19:20.082456 139935010756352                 Options.file_checksum_gen_factory: Unknown
2022/09/28-17:19:20.082459 139935010756352                 Options.best_efforts_recovery: 0
2022/09/28-17:19:20.082462 139935010756352                Options.max_bgerror_resume_count: 2147483647
2022/09/28-17:19:20.082466 139935010756352            Options.bgerror_resume_retry_interval: 1000000
2022/09/28-17:19:20.082470 139935010756352             Options.allow_data_in_errors: 0
2022/09/28-17:19:20.082476 139935010756352             Options.db_host_id: __hostname__
2022/09/28-17:19:20.082482 139935010756352             Options.enforce_single_del_contracts: true
2022/09/28-17:19:20.082488 139935010756352             Options.max_background_jobs: 2
2022/09/28-17:19:20.082492 139935010756352             Options.max_background_compactions: -1
2022/09/28-17:19:20.082495 139935010756352             Options.max_subcompactions: 1
2022/09/28-17:19:20.082498 139935010756352             Options.avoid_flush_during_shutdown: 0
2022/09/28-17:19:20.082501 139935010756352           Options.writable_file_max_buffer_size: 1048576
2022/09/28-17:19:20.082504 139935010756352             Options.delayed_write_rate : 16777216
2022/09/28-17:19:20.082507 139935010756352             Options.max_total_wal_size: 0
2022/09/28-17:19:20.082510 139935010756352             Options.delete_obsolete_files_period_micros: 600000000
2022/09/28-17:19:20.082514 139935010756352                   Options.stats_dump_period_sec: 600
2022/09/28-17:19:20.082518 139935010756352                 Options.stats_persist_period_sec: 600
2022/09/28-17:19:20.082524 139935010756352                 Options.stats_history_buffer_size: 1048576
2022/09/28-17:19:20.082528 139935010756352                          Options.max_open_files: 1000
2022/09/28-17:19:20.082541 139935010756352                          Options.bytes_per_sync: 0
2022/09/28-17:19:20.082545 139935010756352                      Options.wal_bytes_per_sync: 0
2022/09/28-17:19:20.082548 139935010756352                   Options.strict_bytes_per_sync: 0
2022/09/28-17:19:20.082551 139935010756352       Options.compaction_readahead_size: 0
2022/09/28-17:19:20.082554 139935010756352                  Options.max_background_flushes: -1
2022/09/28-17:19:20.082557 139935010756352 Compression algorithms supported:
2022/09/28-17:19:20.082560 139935010756352 	kZSTDNotFinalCompression supported: 0
2022/09/28-17:19:20.082564 139935010756352 	kZSTD supported: 0
2022/09/28-17:19:20.082575 139935010756352 	kXpressCompression supported: 0
2022/09/28-17:19:20.082579 139935010756352 	kLZ4HCCompression supported: 0
2022/09/28-17:19:20.082582 139935010756352 	kLZ4Compression supported: 0
2022/09/28-17:19:20.082586 139935010756352 	kBZip2Compression supported: 0
2022/09/28-17:19:20.082589 139935010756352 	kZlibCompression supported: 0
2022/09/28-17:19:20.082592 139935010756352 	kSnappyCompression supported: 1
2022/09/28-17:19:20.082595 139935010756352 Fast CRC32 supported: Supported on x86
2022/09/28-17:19:20.082598 139935010756352 DMutex implementation: pthread_mutex_t
2022/09/28-17:19:20.082602 139935010756352               Options.comparator: UserKeyComparator
2022/09/28-17:19:20.082605 139935010756352           Options.merge_operator: UserMergeOperator
2022/09/28-17:19:20.082608 139935010756352        Options.compaction_filter: None
2022/09/28-17:19:20.082611 139935010756352        Options.compaction_filter_factory: None
2022/09/28-17:19:20.082615 139935010756352  Options.sst_partitioner_factory: None
2022/09/28-17:19:20.082618 139935010756352         Options.memtable_factory: SkipListFactory
2022/09/28-17:19:20.082621 139935010756352            Options.table_factory: BlockBasedTable
2022/09/28-17:19:20.082638 139935010756352            table_factory options:   flush_block_policy_factory: FlushBlockBySizePolicyFactory (0x6030001cbb20)
  cache_index_and_filter_blocks: 0
  cache_index_and_filter_blocks_with_high_priority: 1
  pin_l0_filter_and_index_blocks_in_cache: 0
  pin_top_level_index_and_filter: 1
  index_type: 0
  data_block_index_type: 0
  index_shortening: 1
  data_block_hash_table_util_ratio: 0.750000
  checksum: 1
  no_block_cache: 0
  block_cache: 0x60d0000014a0
  block_cache_name: LRUCache
  block_cache_options:
    capacity : 2147483648
    num_shard_bits : 6
    strict_capacity_limit : 0
    memory_allocator : None
    high_pri_pool_ratio: 0.500
  block_cache_compressed: (nil)
  persistent_cache: (nil)
  block_size: 4096
  block_size_deviation: 10
  block_restart_interval: 16
  index_block_restart_interval: 1
  metadata_block_size: 4096
  partition_filters: 0
  use_delta_encoding: 1
  filter_policy: bloomfilter
  whole_key_filtering: 1
  verify_compression: 0
  read_amp_bytes_per_bit: 0
  format_version: 5
  enable_i
2022/09/28-17:19:20.082644 139935010756352        Options.write_buffer_size: 4194304
2022/09/28-17:19:20.082647 139935010756352  Options.max_write_buffer_number: 6
2022/09/28-17:19:20.082651 139935010756352        Options.compression[0]: NoCompression
2022/09/28-17:19:20.082654 139935010756352        Options.compression[1]: NoCompression
2022/09/28-17:19:20.082657 139935010756352        Options.compression[2]: Snappy
2022/09/28-17:19:20.082660 139935010756352        Options.compression[3]: Snappy
2022/09/28-17:19:20.082663 139935010756352        Options.compression[4]: Snappy
2022/09/28-17:19:20.082667 139935010756352        Options.compression[5]: Snappy
2022/09/28-17:19:20.082670 139935010756352        Options.compression[6]: Snappy
2022/09/28-17:19:20.082673 139935010756352                  Options.bottommost_compression: Disabled
2022/09/28-17:19:20.082676 139935010756352       Options.prefix_extractor: nullptr
2022/09/28-17:19:20.082679 139935010756352   Options.memtable_insert_with_hint_prefix_extractor: nullptr
2022/09/28-17:19:20.082683 139935010756352             Options.num_levels: 7
2022/09/28-17:19:20.082694 139935010756352        Options.min_write_buffer_number_to_merge: 2
2022/09/28-17:19:20.082697 139935010756352     Options.max_write_buffer_number_to_maintain: 0
2022/09/28-17:19:20.082701 139935010756352     Options.max_write_buffer_size_to_maintain: 0
2022/09/28-17:19:20.082704 139935010756352            Options.bottommost_compression_opts.window_bits: -14
2022/09/28-17:19:20.082707 139935010756352                  Options.bottommost_compression_opts.level: 32767
2022/09/28-17:19:20.082710 139935010756352               Options.bottommost_compression_opts.strategy: 0
2022/09/28-17:19:20.082714 139935010756352         Options.bottommost_compression_opts.max_dict_bytes: 0
2022/09/28-17:19:20.082717 139935010756352         Options.bottommost_compression_opts.zstd_max_train_bytes: 0
2022/09/28-17:19:20.082720 139935010756352         Options.bottommost_compression_opts.parallel_threads: 1
2022/09/28-17:19:20.082723 139935010756352                  Options.bottommost_compression_opts.enabled: false
2022/09/28-17:19:20.082727 139935010756352         Options.bottommost_compression_opts.max_dict_buffer_bytes: 0
2022/09/28-17:19:20.082730 139935010756352         Options.bottommost_compression_opts.use_zstd_dict_trainer: true
2022/09/28-17:19:20.082733 139935010756352            Options.compression_opts.window_bits: -14
2022/09/28-17:19:20.082736 139935010756352                  Options.compression_opts.level: 32767
2022/09/28-17:19:20.082740 139935010756352               Options.compression_opts.strategy: 0
2022/09/28-17:19:20.082743 139935010756352         Options.compression_opts.max_dict_bytes: 0
2022/09/28-17:19:20.082746 139935010756352         Options.compression_opts.zstd_max_train_bytes: 0
2022/09/28-17:19:20.082749 139935010756352         Options.compression_opts.use_zstd_dict_trainer: true
2022/09/28-17:19:20.082753 139935010756352         Options.compression_opts.parallel_threads: 1
2022/09/28-17:19:20.082756 139935010756352                  Options.compression_opts.enabled: false
2022/09/28-17:19:20.082759 139935010756352         Options.compression_opts.max_dict_buffer_bytes: 0
2022/09/28-17:19:20.082762 139935010756352      Options.level0_file_num_compaction_trigger: 2
2022/09/28-17:19:20.082765 139935010756352          Options.level0_slowdown_writes_trigger: 20
2022/09/28-17:19:20.082769 139935010756352              Options.level0_stop_writes_trigger: 36
2022/09/28-17:19:20.082772 139935010756352                   Options.target_file_size_base: 2097152
2022/09/28-17:19:20.082775 139935010756352             Options.target_file_size_multiplier: 1
2022/09/28-17:19:20.082778 139935010756352                Options.max_bytes_for_level_base: 16777216
2022/09/28-17:19:20.082781 139935010756352 Options.level_compaction_dynamic_level_bytes: 0
2022/09/28-17:19:20.082784 139935010756352          Options.max_bytes_for_level_multiplier: 10.000000
2022/09/28-17:19:20.082787 139935010756352 Options.max_bytes_for_level_multiplier_addtl[0]: 1
2022/09/28-17:19:20.082791 139935010756352 Options.max_bytes_for_level_multiplier_addtl[1]: 1
2022/09/28-17:19:20.082794 139935010756352 Options.max_bytes_for_level_multiplier_addtl[2]: 1
2022/09/28-17:19:20.082797 139935010756352 Options.max_bytes_for_level_multiplier_addtl[3]: 1
2022/09/28-17:19:20.082800 139935010756352 Options.max_bytes_for_level_multiplier_addtl[4]: 1
2022/09/28-17:19:20.082803 139935010756352 Options.max_bytes_for_level_multiplier_addtl[5]: 1
2022/09/28-17:19:20.082806 139935010756352 Options.max_bytes_for_level_multiplier_addtl[6]: 1
2022/09/28-17:19:20.082809 139935010756352       Options.max_sequential_skip_in_iterations: 8
2022/09/28-17:19:20.082812 139935010756352                    Options.max_compaction_bytes: 52428800
2022/09/28-17:19:20.082815 139935010756352                        Options.arena_block_size: 524288
2022/09/28-17:19:20.082818 139935010756352   Options.soft_pending_compaction_bytes_limit: 68719476736
2022/09/28-17:19:20.082822 139935010756352   Options.hard_pending_compaction_bytes_limit: 274877906944
2022/09/28-17:19:20.082829 139935010756352                Options.disable_auto_compactions: 0
2022/09/28-17:19:20.082832 139935010756352                        Options.compaction_style: kCompactionStyleLevel
2022/09/28-17:19:20.082836 139935010756352                          Options.compaction_pri: kMinOverlappingRatio
2022/09/28-17:19:20.082839 139935010756352 Options.compaction_options_universal.size_ratio: 1
2022/09/28-17:19:20.082842 139935010756352 Options.compaction_options_universal.min_merge_width: 2
2022/09/28-17:19:20.082845 139935010756352 Options.compaction_options_universal.max_merge_width: 4294967295
2022/09/28-17:19:20.082848 139935010756352 Options.compaction_options_universal.max_size_amplification_percent: 200
2022/09/28-17:19:20.082852 139935010756352 Options.compaction_options_universal.compression_size_percent: -1
2022/09/28-17:19:20.082855 139935010756352 Options.compaction_options_universal.stop_style: kCompactionStopStyleTotalSize
2022/09/28-17:19:20.082858 139935010756352 Options.compaction_options_fifo.max_table_files_size: 1073741824
2022/09/28-17:19:20.082861 139935010756352 Options.compaction_options_fifo.allow_compaction: 0
2022/09/28-17:19:20.082865 139935010756352                   Options.table_properties_collectors: 
2022/09/28-17:19:20.082868 139935010756352                   Options.inplace_update_support: 0
2022/09/28-17:19:20.082871 139935010756352                 Options.inplace_update_num_locks: 10000
2022/09/28-17:19:20.082874 139935010756352               Options.memtable_prefix_bloom_size_ratio: 0.000000
2022/09/28-17:19:20.082877 139935010756352               Options.memtable_whole_key_filtering: 0
2022/09/28-17:19:20.082880 139935010756352   Options.memtable_huge_page_size: 0
2022/09/28-17:19:20.082883 139935010756352                           Options.bloom_locality: 0
2022/09/28-17:19:20.082886 139935010756352                    Options.max_successive_merges: 0
2022/09/28-17:19:20.082890 139935010756352                Options.optimize_filters_for_hits: 0
2022/09/28-17:19:20.082893 139935010756352                Options.paranoid_file_checks: 0
2022/09/28-17:19:20.082896 139935010756352                Options.force_consistency_checks: 1
2022/09/28-17:19:20.082899 139935010756352                Options.report_bg_io_stats: 0
2022/09/28-17:19:20.082902 139935010756352                               Options.ttl: 2592000
2022/09/28-17:19:20.082905 139935010756352          Options.periodic_compaction_seconds: 0
2022/09/28-17:19:20.082908 139935010756352  Options.preclude_last_level_data_seconds: 0
2022/09/28-17:19:20.082911 139935010756352                       Options.enable_blob_files: false
2022/09/28-17:19:20.082915 139935010756352                           Options.min_blob_size: 0
2022/09/28-17:19:20.082918 139935010756352                          Options.blob_file_size: 268435456
2022/09/28-17:19:20.082921 139935010756352                   Options.blob_compression_type: NoCompression
2022/09/28-17:19:20.082924 139935010756352          Options.enable_blob_garbage_collection: false
2022/09/28-17:19:20.082927 139935010756352      Options.blob_garbage_collection_age_cutoff: 0.250000
2022/09/28-17:19:20.082931 139935010756352 Options.blob_garbage_collection_force_threshold: 1.000000
2022/09/28-17:19:20.082934 139935010756352          Options.blob_compaction_readahead_size: 0
2022/09/28-17:19:20.082937 139935010756352                Options.blob_file_starting_level: 0
2022/09/28-17:19:20.082940 139935010756352 Options.experimental_mempurge_threshold: 0.000000
2022/09/28-17:19:20.082943 139935010756352               Options.comparator: UserKeyComparator.ts
2022/09/28-17:19:20.082947 139935010756352           Options.merge_operator: None
2022/09/28-17:19:20.082950 139935010756352        Options.compaction_filter: None
2022/09/28-17:19:20.082953 139935010756352        Options.compaction_filter_factory: UserCompactionFilterFactory
2022/09/28-17:19:20.082956 139935010756352  Options.sst_partitioner_factory: None
2022/09/28-17:19:20.082959 139935010756352         Options.memtable_factory: SkipListFactory
2022/09/28-17:19:20.082966 139935010756352            Options.table_factory: BlockBasedTable
2022/09/28-17:19:20.082981 139935010756352            table_factory options:   flush_block_policy_factory: FlushBlockBySizePolicyFactory (0x6030001cc9c0)
  cache_index_and_filter_blocks: 1
  cache_index_and_filter_blocks_with_high_priority: 1
  pin_l0_filter_and_index_blocks_in_cache: 0
  pin_top_level_index_and_filter: 1
  index_type: 2
  data_block_index_type: 0
  index_shortening: 1
  data_block_hash_table_util_ratio: 0.750000
  checksum: 1
  no_block_cache: 0
  block_cache: 0x60d000026b70
  block_cache_name: LRUCache
  block_cache_options:
    capacity : 8388608
    num_shard_bits : 4
    strict_capacity_limit : 0
    memory_allocator : None
    high_pri_pool_ratio: 0.000
  block_cache_compressed: (nil)
  persistent_cache: (nil)
  block_size: 4096
  block_size_deviation: 10
  block_restart_interval: 16
  index_block_restart_interval: 1
  metadata_block_size: 4096
  partition_filters: 0
  use_delta_encoding: 1
  filter_policy: nullptr
  whole_key_filtering: 1
  verify_compression: 0
  read_amp_bytes_per_bit: 0
  format_version: 5
  enable_index_co
2022/09/28-17:19:20.082987 139935010756352        Options.write_buffer_size: 2097152
2022/09/28-17:19:20.082990 139935010756352  Options.max_write_buffer_number: 6
2022/09/28-17:19:20.082994 139935010756352        Options.compression[0]: NoCompression
2022/09/28-17:19:20.082997 139935010756352        Options.compression[1]: NoCompression
2022/09/28-17:19:20.083000 139935010756352        Options.compression[2]: Snappy
2022/09/28-17:19:20.083003 139935010756352        Options.compression[3]: Snappy
2022/09/28-17:19:20.083006 139935010756352        Options.compression[4]: Snappy
2022/09/28-17:19:20.083009 139935010756352        Options.compression[5]: Snappy
2022/09/28-17:19:20.083012 139935010756352        Options.compression[6]: Snappy
2022/09/28-17:19:20.083015 139935010756352                  Options.bottommost_compression: Disabled
2022/09/28-17:19:20.083019 139935010756352       Options.prefix_extractor: nullptr
2022/09/28-17:19:20.083022 139935010756352   Options.memtable_insert_with_hint_prefix_extractor: nullptr
2022/09/28-17:19:20.083025 139935010756352             Options.num_levels: 7
2022/09/28-17:19:20.083028 139935010756352        Options.min_write_buffer_number_to_merge: 2
2022/09/28-17:19:20.083031 139935010756352     Options.max_write_buffer_number_to_maintain: 0
2022/09/28-17:19:20.083035 139935010756352     Options.max_write_buffer_size_to_maintain: 0
2022/09/28-17:19:20.083038 139935010756352            Options.bottommost_compression_opts.window_bits: -14
2022/09/28-17:19:20.083041 139935010756352                  Options.bottommost_compression_opts.level: 32767
2022/09/28-17:19:20.083044 139935010756352               Options.bottommost_compression_opts.strategy: 0
2022/09/28-17:19:20.083047 139935010756352         Options.bottommost_compression_opts.max_dict_bytes: 0
2022/09/28-17:19:20.083051 139935010756352         Options.bottommost_compression_opts.zstd_max_train_bytes: 0
2022/09/28-17:19:20.083054 139935010756352         Options.bottommost_compression_opts.parallel_threads: 1
2022/09/28-17:19:20.083057 139935010756352                  Options.bottommost_compression_opts.enabled: false
2022/09/28-17:19:20.083060 139935010756352         Options.bottommost_compression_opts.max_dict_buffer_bytes: 0
2022/09/28-17:19:20.083063 139935010756352         Options.bottommost_compression_opts.use_zstd_dict_trainer: true
2022/09/28-17:19:20.083067 139935010756352            Options.compression_opts.window_bits: -14
2022/09/28-17:19:20.083070 139935010756352                  Options.compression_opts.level: 32767
2022/09/28-17:19:20.083073 139935010756352               Options.compression_opts.strategy: 0
2022/09/28-17:19:20.083076 139935010756352         Options.compression_opts.max_dict_bytes: 0
2022/09/28-17:19:20.083079 139935010756352         Options.compression_opts.zstd_max_train_bytes: 0
2022/09/28-17:19:20.083082 139935010756352         Options.compression_opts.use_zstd_dict_trainer: true
2022/09/28-17:19:20.083090 139935010756352         Options.compression_opts.parallel_threads: 1
2022/09/28-17:19:20.083093 139935010756352                  Options.compression_opts.enabled: false
2022/09/28-17:19:20.083096 139935010756352         Options.compression_opts.max_dict_buffer_bytes: 0
2022/09/28-17:19:20.083099 139935010756352      Options.level0_file_num_compaction_trigger: 2
2022/09/28-17:19:20.083103 139935010756352          Options.level0_slowdown_writes_trigger: 20
2022/09/28-17:19:20.083106 139935010756352              Options.level0_stop_writes_trigger: 36
2022/09/28-17:19:20.083109 139935010756352                   Options.target_file_size_base: 2097152
2022/09/28-17:19:20.083112 139935010756352             Options.target_file_size_multiplier: 1
2022/09/28-17:19:20.083115 139935010756352                Options.max_bytes_for_level_base: 10485760
2022/09/28-17:19:20.083118 139935010756352 Options.level_compaction_dynamic_level_bytes: 0
2022/09/28-17:19:20.083121 139935010756352          Options.max_bytes_for_level_multiplier: 10.000000
2022/09/28-17:19:20.083125 139935010756352 Options.max_bytes_for_level_multiplier_addtl[0]: 1
2022/09/28-17:19:20.083128 139935010756352 Options.max_bytes_for_level_multiplier_addtl[1]: 1
2022/09/28-17:19:20.083131 139935010756352 Options.max_bytes_for_level_multiplier_addtl[2]: 1
2022/09/28-17:19:20.083134 139935010756352 Options.max_bytes_for_level_multiplier_addtl[3]: 1
2022/09/28-17:19:20.083137 139935010756352 Options.max_bytes_for_level_multiplier_addtl[4]: 1
2022/09/28-17:19:20.083140 139935010756352 Options.max_bytes_for_level_multiplier_addtl[5]: 1
2022/09/28-17:19:20.083143 139935010756352 Options.max_bytes_for_level_multiplier_addtl[6]: 1
2022/09/28-17:19:20.083146 139935010756352       Options.max_sequential_skip_in_iterations: 8
2022/09/28-17:19:20.083149 139935010756352                    Options.max_compaction_bytes: 52428800
2022/09/28-17:19:20.083152 139935010756352                        Options.arena_block_size: 262144
2022/09/28-17:19:20.083155 139935010756352   Options.soft_pending_compaction_bytes_limit: 268435456
2022/09/28-17:19:20.083159 139935010756352   Options.hard_pending_compaction_bytes_limit: 1073741824
2022/09/28-17:19:20.083162 139935010756352                Options.disable_auto_compactions: 0
2022/09/28-17:19:20.083165 139935010756352                        Options.compaction_style: kCompactionStyleLevel
2022/09/28-17:19:20.083168 139935010756352                          Options.compaction_pri: kMinOverlappingRatio
2022/09/28-17:19:20.083171 139935010756352 Options.compaction_options_universal.size_ratio: 1
2022/09/28-17:19:20.083174 139935010756352 Options.compaction_options_universal.min_merge_width: 2
2022/09/28-17:19:20.083177 139935010756352 Options.compaction_options_universal.max_merge_width: 4294967295
2022/09/28-17:19:20.083181 139935010756352 Options.compaction_options_universal.max_size_amplification_percent: 200
2022/09/28-17:19:20.083184 139935010756352 Options.compaction_options_universal.compression_size_percent: -1
2022/09/28-17:19:20.083187 139935010756352 Options.compaction_options_universal.stop_style: kCompactionStopStyleTotalSize
2022/09/28-17:19:20.083190 139935010756352 Options.compaction_options_fifo.max_table_files_size: 1073741824
2022/09/28-17:19:20.083194 139935010756352 Options.compaction_options_fifo.allow_compaction: 0
2022/09/28-17:19:20.083197 139935010756352                   Options.table_properties_collectors: 
2022/09/28-17:19:20.083200 139935010756352                   Options.inplace_update_support: 0
2022/09/28-17:19:20.083203 139935010756352                 Options.inplace_update_num_locks: 10000
2022/09/28-17:19:20.083206 139935010756352               Options.memtable_prefix_bloom_size_ratio: 0.000000
2022/09/28-17:19:20.083209 139935010756352               Options.memtable_whole_key_filtering: 0
2022/09/28-17:19:20.083212 139935010756352   Options.memtable_huge_page_size: 0
2022/09/28-17:19:20.083215 139935010756352                           Options.bloom_locality: 0
2022/09/28-17:19:20.083222 139935010756352                    Options.max_successive_merges: 0
2022/09/28-17:19:20.083226 139935010756352                Options.optimize_filters_for_hits: 0
2022/09/28-17:19:20.083229 139935010756352                Options.paranoid_file_checks: 0
2022/09/28-17:19:20.083232 139935010756352                Options.force_consistency_checks: 1
2022/09/28-17:19:20.083235 139935010756352                Options.report_bg_io_stats: 0
2022/09/28-17:19:20.083238 139935010756352                               Options.ttl: 2592000
2022/09/28-17:19:20.083241 139935010756352          Options.periodic_compaction_seconds: 2592000
2022/09/28-17:19:20.083245 139935010756352  Options.preclude_last_level_data_seconds: 0
2022/09/28-17:19:20.083248 139935010756352                       Options.enable_blob_files: false
2022/09/28-17:19:20.083251 139935010756352                           Options.min_blob_size: 0
2022/09/28-17:19:20.083254 139935010756352                          Options.blob_file_size: 268435456
2022/09/28-17:19:20.083257 139935010756352                   Options.blob_compression_type: NoCompression
2022/09/28-17:19:20.083260 139935010756352          Options.enable_blob_garbage_collection: false
2022/09/28-17:19:20.083263 139935010756352      Options.blob_garbage_collection_age_cutoff: 0.250000
2022/09/28-17:19:20.083267 139935010756352 Options.blob_garbage_collection_force_threshold: 1.000000
2022/09/28-17:19:20.083270 139935010756352          Options.blob_compaction_readahead_size: 0
2022/09/28-17:19:20.083273 139935010756352                Options.blob_file_starting_level: 0
2022/09/28-17:19:20.083276 139935010756352 Options.experimental_mempurge_threshold: 0.000000
2022/09/28-17:19:20.083279 139935010756352 DB pointer 0x62300001a500
2022/09/28-17:19:20.083283 139935010756352 (Original Log Time 2022/09/28-17:19:20.081353) [db/compaction/compaction_job.cc:1449] [__internal__] [JOB 3240] Compacted 1@1 files to L1 => 3449 bytes
2022/09/28-17:19:20.083290 139935010756352 (Original Log Time 2022/09/28-17:19:20.081650) [db/compaction/compaction_job.cc:688] [__internal__] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 2.9 rd, 2.9 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 80, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.083306 139935010756352 (Original Log Time 2022/09/28-17:19:20.081702) EVENT_LOG_v1 {"time_micros": 1664356760081672, "job": 3240, "event": "compaction_finished", "compaction_time_micros": 1198, "compaction_time_cpu_micros": 1085, "output_level": 1, "num_output_files": 1, "total_output_size": 3449, "num_input_records": 80, "num_output_records": 80, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.083412 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452014.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.083443 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760083435, "job": 3240, "event": "table_file_deletion", "file_number": 1452014}
2022/09/28-17:19:20.083497 139935010756352 [db/compaction/compaction_job.cc:1774] [default] [JOB 3241] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.083509 139935010756352 [db/compaction/compaction_job.cc:1778] [default] Compaction start summary: Base version 3242 Base level 1, inputs: [1452015(1712B)]
2022/09/28-17:19:20.083545 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760083521, "job": 3241, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452015], "score": 0.000102043, "input_data_size": 1712}
2022/09/28-17:19:20.084256 139935010756352 [db/compaction/compaction_job.cc:1376] [default] [JOB 3241] Generated table #1452017: 10 keys, 1712 bytes, temperature: kUnknown
2022/09/28-17:19:20.084371 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760084281, "cf_name": "default", "job": 3241, "event": "table_file_creation", "file_number": 1452017, "file_size": 1712, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 533, "index_size": 49, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 69, "raw_key_size": 390, "raw_average_key_size": 39, "raw_value_size": 262, "raw_average_value_size": 26, "num_data_blocks": 1, "num_entries": 10, "num_filter_entries": 10, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "bloomfilter", "column_family_name": "default", "column_family_id": 0, "comparator": "UserKeyComparator", "merge_operator": "UserMergeOperator", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452017, "seqno_to_time_mapping": "N/A"}}
2022/09/28-17:19:20.085057 139935010756352 (Original Log Time 2022/09/28-17:19:20.084638) [db/compaction/compaction_job.cc:1449] [default] [JOB 3241] Compacted 1@1 files to L1 => 1712 bytes
2022/09/28-17:19:20.085069 139935010756352 (Original Log Time 2022/09/28-17:19:20.084934) [db/compaction/compaction_job.cc:688] [default] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 2.0 rd, 2.0 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 10, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.085090 139935010756352 (Original Log Time 2022/09/28-17:19:20.085005) EVENT_LOG_v1 {"time_micros": 1664356760084966, "job": 3241, "event": "compaction_finished", "compaction_time_micros": 860, "compaction_time_cpu_micros": 706, "output_level": 1, "num_output_files": 1, "total_output_size": 1712, "num_input_records": 10, "num_output_records": 10, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.085243 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452015.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.085283 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760085272, "job": 3241, "event": "table_file_deletion", "file_number": 1452015}
2022/09/28-17:19:20.085357 139935010756352 [db/compaction/compaction_job.cc:1774] [__internal__] [JOB 3242] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.085372 139935010756352 [db/compaction/compaction_job.cc:1778] [__internal__] Compaction start summary: Base version 3243 Base level 1, inputs: [1452016(3449B)]
2022/09/28-17:19:20.085413 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760085388, "job": 3242, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452016], "score": 0.000328922, "input_data_size": 3449}
2022/09/28-17:19:20.086738 139935010756352 [db/compaction/compaction_job.cc:1376] [__internal__] [JOB 3242] Generated table #1452018: 80 keys, 3449 bytes, temperature: kUnknown
2022/09/28-17:19:20.086912 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760086778, "cf_name": "__internal__", "job": 3242, "event": "table_file_creation", "file_number": 1452018, "file_size": 3449, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 2214, "index_size": 169, "index_partitions": 1, "top_level_index_size": 82, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 0, "raw_key_size": 6170, "raw_average_key_size": 77, "raw_value_size": 120, "raw_average_value_size": 1, "num_data_blocks": 1, "num_entries": 80, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "__internal__", "column_family_id": 1, "comparator": "UserKeyComparator.ts", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452018, "seqno_to_time_mapping": "N/A", "rocksdb.timestamp_max": "E300000000000000", "rocksdb.timestamp_min": "0000000000000000"}}
2022/09/28-17:19:20.087755 139935010756352 (Original Log Time 2022/09/28-17:19:20.087271) [db/compaction/compaction_job.cc:1449] [__internal__] [JOB 3242] Compacted 1@1 files to L1 => 3449 bytes
2022/09/28-17:19:20.087766 139935010756352 (Original Log Time 2022/09/28-17:19:20.087641) [db/compaction/compaction_job.cc:688] [__internal__] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 2.2 rd, 2.2 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 80, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.087785 139935010756352 (Original Log Time 2022/09/28-17:19:20.087703) EVENT_LOG_v1 {"time_micros": 1664356760087667, "job": 3242, "event": "compaction_finished", "compaction_time_micros": 1556, "compaction_time_cpu_micros": 1391, "output_level": 1, "num_output_files": 1, "total_output_size": 3449, "num_input_records": 80, "num_output_records": 80, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.087930 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452016.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.087967 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760087958, "job": 3242, "event": "table_file_deletion", "file_number": 1452016}
2022/09/28-17:19:20.088040 139935010756352 [db/compaction/compaction_job.cc:1774] [default] [JOB 3243] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.088055 139935010756352 [db/compaction/compaction_job.cc:1778] [default] Compaction start summary: Base version 3244 Base level 1, inputs: [1452017(1712B)]
2022/09/28-17:19:20.088094 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760088069, "job": 3243, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452017], "score": 0.000102043, "input_data_size": 1712}
2022/09/28-17:19:20.088890 139935010756352 [db/compaction/compaction_job.cc:1376] [default] [JOB 3243] Generated table #1452019: 10 keys, 1712 bytes, temperature: kUnknown
2022/09/28-17:19:20.089051 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760088923, "cf_name": "default", "job": 3243, "event": "table_file_creation", "file_number": 1452019, "file_size": 1712, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 533, "index_size": 49, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 69, "raw_key_size": 390, "raw_average_key_size": 39, "raw_value_size": 262, "raw_average_value_size": 26, "num_data_blocks": 1, "num_entries": 10, "num_filter_entries": 10, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "bloomfilter", "column_family_name": "default", "column_family_id": 0, "comparator": "UserKeyComparator", "merge_operator": "UserMergeOperator", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452019, "seqno_to_time_mapping": "N/A"}}
2022/09/28-17:19:20.089807 139935010756352 (Original Log Time 2022/09/28-17:19:20.089371) [db/compaction/compaction_job.cc:1449] [default] [JOB 3243] Compacted 1@1 files to L1 => 1712 bytes
2022/09/28-17:19:20.089818 139935010756352 (Original Log Time 2022/09/28-17:19:20.089703) [db/compaction/compaction_job.cc:688] [default] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 1.7 rd, 1.7 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 10, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.089838 139935010756352 (Original Log Time 2022/09/28-17:19:20.089763) EVENT_LOG_v1 {"time_micros": 1664356760089728, "job": 3243, "event": "compaction_finished", "compaction_time_micros": 1003, "compaction_time_cpu_micros": 841, "output_level": 1, "num_output_files": 1, "total_output_size": 1712, "num_input_records": 10, "num_output_records": 10, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.089963 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452017.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.090004 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760089990, "job": 3243, "event": "table_file_deletion", "file_number": 1452017}
2022/09/28-17:19:20.090090 139935010756352 [db/compaction/compaction_job.cc:1774] [__internal__] [JOB 3244] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.090106 139935010756352 [db/compaction/compaction_job.cc:1778] [__internal__] Compaction start summary: Base version 3245 Base level 1, inputs: [1452018(3449B)]
2022/09/28-17:19:20.090144 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760090121, "job": 3244, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452018], "score": 0.000328922, "input_data_size": 3449}
2022/09/28-17:19:20.091327 139935010756352 [db/compaction/compaction_job.cc:1376] [__internal__] [JOB 3244] Generated table #1452020: 80 keys, 3449 bytes, temperature: kUnknown
2022/09/28-17:19:20.091464 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760091359, "cf_name": "__internal__", "job": 3244, "event": "table_file_creation", "file_number": 1452020, "file_size": 3449, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 2214, "index_size": 169, "index_partitions": 1, "top_level_index_size": 82, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 0, "raw_key_size": 6170, "raw_average_key_size": 77, "raw_value_size": 120, "raw_average_value_size": 1, "num_data_blocks": 1, "num_entries": 80, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "__internal__", "column_family_id": 1, "comparator": "UserKeyComparator.ts", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452020, "seqno_to_time_mapping": "N/A", "rocksdb.timestamp_max": "E300000000000000", "rocksdb.timestamp_min": "0000000000000000"}}
2022/09/28-17:19:20.092263 139935010756352 (Original Log Time 2022/09/28-17:19:20.091823) [db/compaction/compaction_job.cc:1449] [__internal__] [JOB 3244] Compacted 1@1 files to L1 => 3449 bytes
2022/09/28-17:19:20.092274 139935010756352 (Original Log Time 2022/09/28-17:19:20.092148) [db/compaction/compaction_job.cc:688] [__internal__] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 2.5 rd, 2.5 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 80, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.092293 139935010756352 (Original Log Time 2022/09/28-17:19:20.092212) EVENT_LOG_v1 {"time_micros": 1664356760092176, "job": 3244, "event": "compaction_finished", "compaction_time_micros": 1372, "compaction_time_cpu_micros": 1235, "output_level": 1, "num_output_files": 1, "total_output_size": 3449, "num_input_records": 80, "num_output_records": 80, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.092422 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452018.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.092458 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760092448, "job": 3244, "event": "table_file_deletion", "file_number": 1452018}
2022/09/28-17:19:20.092532 139935010756352 [db/compaction/compaction_job.cc:1774] [default] [JOB 3245] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.092546 139935010756352 [db/compaction/compaction_job.cc:1778] [default] Compaction start summary: Base version 3246 Base level 1, inputs: [1452019(1712B)]
2022/09/28-17:19:20.092601 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760092560, "job": 3245, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452019], "score": 0.000102043, "input_data_size": 1712}
2022/09/28-17:19:20.093342 139935010756352 [db/compaction/compaction_job.cc:1376] [default] [JOB 3245] Generated table #1452021: 10 keys, 1712 bytes, temperature: kUnknown
2022/09/28-17:19:20.093474 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760093373, "cf_name": "default", "job": 3245, "event": "table_file_creation", "file_number": 1452021, "file_size": 1712, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 533, "index_size": 49, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 69, "raw_key_size": 390, "raw_average_key_size": 39, "raw_value_size": 262, "raw_average_value_size": 26, "num_data_blocks": 1, "num_entries": 10, "num_filter_entries": 10, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "bloomfilter", "column_family_name": "default", "column_family_id": 0, "comparator": "UserKeyComparator", "merge_operator": "UserMergeOperator", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452021, "seqno_to_time_mapping": "N/A"}}
2022/09/28-17:19:20.094254 139935010756352 (Original Log Time 2022/09/28-17:19:20.093803) [db/compaction/compaction_job.cc:1449] [default] [JOB 3245] Compacted 1@1 files to L1 => 1712 bytes
2022/09/28-17:19:20.094271 139935010756352 (Original Log Time 2022/09/28-17:19:20.094147) [db/compaction/compaction_job.cc:688] [default] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 1.9 rd, 1.9 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 10, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.094291 139935010756352 (Original Log Time 2022/09/28-17:19:20.094208) EVENT_LOG_v1 {"time_micros": 1664356760094172, "job": 3245, "event": "compaction_finished", "compaction_time_micros": 911, "compaction_time_cpu_micros": 795, "output_level": 1, "num_output_files": 1, "total_output_size": 1712, "num_input_records": 10, "num_output_records": 10, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.094415 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452019.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.094451 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760094442, "job": 3245, "event": "table_file_deletion", "file_number": 1452019}
2022/09/28-17:19:20.094518 139935010756352 [db/compaction/compaction_job.cc:1774] [__internal__] [JOB 3246] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.094532 139935010756352 [db/compaction/compaction_job.cc:1778] [__internal__] Compaction start summary: Base version 3247 Base level 1, inputs: [1452020(3449B)]
2022/09/28-17:19:20.094597 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760094551, "job": 3246, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452020], "score": 0.000328922, "input_data_size": 3449}
2022/09/28-17:19:20.095766 139935010756352 [db/compaction/compaction_job.cc:1376] [__internal__] [JOB 3246] Generated table #1452022: 80 keys, 3449 bytes, temperature: kUnknown
2022/09/28-17:19:20.095890 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760095798, "cf_name": "__internal__", "job": 3246, "event": "table_file_creation", "file_number": 1452022, "file_size": 3449, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 2214, "index_size": 169, "index_partitions": 1, "top_level_index_size": 82, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 0, "raw_key_size": 6170, "raw_average_key_size": 77, "raw_value_size": 120, "raw_average_value_size": 1, "num_data_blocks": 1, "num_entries": 80, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "__internal__", "column_family_id": 1, "comparator": "UserKeyComparator.ts", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452022, "seqno_to_time_mapping": "N/A", "rocksdb.timestamp_max": "E300000000000000", "rocksdb.timestamp_min": "0000000000000000"}}
2022/09/28-17:19:20.096745 139935010756352 (Original Log Time 2022/09/28-17:19:20.096208) [db/compaction/compaction_job.cc:1449] [__internal__] [JOB 3246] Compacted 1@1 files to L1 => 3449 bytes
2022/09/28-17:19:20.096760 139935010756352 (Original Log Time 2022/09/28-17:19:20.096556) [db/compaction/compaction_job.cc:688] [__internal__] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 2.6 rd, 2.6 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 80, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.096785 139935010756352 (Original Log Time 2022/09/28-17:19:20.096653) EVENT_LOG_v1 {"time_micros": 1664356760096606, "job": 3246, "event": "compaction_finished", "compaction_time_micros": 1348, "compaction_time_cpu_micros": 1209, "output_level": 1, "num_output_files": 1, "total_output_size": 3449, "num_input_records": 80, "num_output_records": 80, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.096987 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452020.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.097039 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760097025, "job": 3246, "event": "table_file_deletion", "file_number": 1452020}
2022/09/28-17:19:20.097149 139935010756352 [db/compaction/compaction_job.cc:1774] [default] [JOB 3247] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.097170 139935010756352 [db/compaction/compaction_job.cc:1778] [default] Compaction start summary: Base version 3248 Base level 1, inputs: [1452021(1712B)]
2022/09/28-17:19:20.097222 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760097190, "job": 3247, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452021], "score": 0.000102043, "input_data_size": 1712}
2022/09/28-17:19:20.098250 139935010756352 [db/compaction/compaction_job.cc:1376] [default] [JOB 3247] Generated table #1452023: 10 keys, 1712 bytes, temperature: kUnknown
2022/09/28-17:19:20.098424 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760098294, "cf_name": "default", "job": 3247, "event": "table_file_creation", "file_number": 1452023, "file_size": 1712, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 533, "index_size": 49, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 69, "raw_key_size": 390, "raw_average_key_size": 39, "raw_value_size": 262, "raw_average_value_size": 26, "num_data_blocks": 1, "num_entries": 10, "num_filter_entries": 10, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "bloomfilter", "column_family_name": "default", "column_family_id": 0, "comparator": "UserKeyComparator", "merge_operator": "UserMergeOperator", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452023, "seqno_to_time_mapping": "N/A"}}
2022/09/28-17:19:20.099443 139935010756352 (Original Log Time 2022/09/28-17:19:20.098864) [db/compaction/compaction_job.cc:1449] [default] [JOB 3247] Compacted 1@1 files to L1 => 1712 bytes
2022/09/28-17:19:20.099458 139935010756352 (Original Log Time 2022/09/28-17:19:20.099300) [db/compaction/compaction_job.cc:688] [default] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 1.4 rd, 1.4 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 10, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.099482 139935010756352 (Original Log Time 2022/09/28-17:19:20.099380) EVENT_LOG_v1 {"time_micros": 1664356760099335, "job": 3247, "event": "compaction_finished", "compaction_time_micros": 1264, "compaction_time_cpu_micros": 1112, "output_level": 1, "num_output_files": 1, "total_output_size": 1712, "num_input_records": 10, "num_output_records": 10, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.099682 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452021.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.099733 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760099720, "job": 3247, "event": "table_file_deletion", "file_number": 1452021}
2022/09/28-17:19:20.099835 139935010756352 [db/compaction/compaction_job.cc:1774] [__internal__] [JOB 3248] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.099856 139935010756352 [db/compaction/compaction_job.cc:1778] [__internal__] Compaction start summary: Base version 3249 Base level 1, inputs: [1452022(3449B)]
2022/09/28-17:19:20.099908 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760099876, "job": 3248, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452022], "score": 0.000328922, "input_data_size": 3449}
2022/09/28-17:19:20.101563 139935010756352 [db/compaction/compaction_job.cc:1376] [__internal__] [JOB 3248] Generated table #1452024: 80 keys, 3449 bytes, temperature: kUnknown
2022/09/28-17:19:20.101760 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760101622, "cf_name": "__internal__", "job": 3248, "event": "table_file_creation", "file_number": 1452024, "file_size": 3449, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 2214, "index_size": 169, "index_partitions": 1, "top_level_index_size": 82, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 0, "raw_key_size": 6170, "raw_average_key_size": 77, "raw_value_size": 120, "raw_average_value_size": 1, "num_data_blocks": 1, "num_entries": 80, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "__internal__", "column_family_id": 1, "comparator": "UserKeyComparator.ts", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452024, "seqno_to_time_mapping": "N/A", "rocksdb.timestamp_max": "E300000000000000", "rocksdb.timestamp_min": "0000000000000000"}}
2022/09/28-17:19:20.102791 139935010756352 (Original Log Time 2022/09/28-17:19:20.102252) [db/compaction/compaction_job.cc:1449] [__internal__] [JOB 3248] Compacted 1@1 files to L1 => 3449 bytes
2022/09/28-17:19:20.102801 139935010756352 (Original Log Time 2022/09/28-17:19:20.102684) [db/compaction/compaction_job.cc:688] [__internal__] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 1.8 rd, 1.8 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 80, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.102817 139935010756352 (Original Log Time 2022/09/28-17:19:20.102742) EVENT_LOG_v1 {"time_micros": 1664356760102711, "job": 3248, "event": "compaction_finished", "compaction_time_micros": 1932, "compaction_time_cpu_micros": 1735, "output_level": 1, "num_output_files": 1, "total_output_size": 3449, "num_input_records": 80, "num_output_records": 80, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.102939 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452022.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.102974 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760102965, "job": 3248, "event": "table_file_deletion", "file_number": 1452022}
2022/09/28-17:19:20.103045 139935010756352 [db/compaction/compaction_job.cc:1774] [default] [JOB 3249] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.103059 139935010756352 [db/compaction/compaction_job.cc:1778] [default] Compaction start summary: Base version 3250 Base level 1, inputs: [1452023(1712B)]
2022/09/28-17:19:20.103111 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760103074, "job": 3249, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452023], "score": 0.000102043, "input_data_size": 1712}
2022/09/28-17:19:20.103837 139935010756352 [db/compaction/compaction_job.cc:1376] [default] [JOB 3249] Generated table #1452025: 10 keys, 1712 bytes, temperature: kUnknown
2022/09/28-17:19:20.103953 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760103866, "cf_name": "default", "job": 3249, "event": "table_file_creation", "file_number": 1452025, "file_size": 1712, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 533, "index_size": 49, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 69, "raw_key_size": 390, "raw_average_key_size": 39, "raw_value_size": 262, "raw_average_value_size": 26, "num_data_blocks": 1, "num_entries": 10, "num_filter_entries": 10, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "bloomfilter", "column_family_name": "default", "column_family_id": 0, "comparator": "UserKeyComparator", "merge_operator": "UserMergeOperator", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452025, "seqno_to_time_mapping": "N/A"}}
2022/09/28-17:19:20.104661 139935010756352 (Original Log Time 2022/09/28-17:19:20.104251) [db/compaction/compaction_job.cc:1449] [default] [JOB 3249] Compacted 1@1 files to L1 => 1712 bytes
2022/09/28-17:19:20.104670 139935010756352 (Original Log Time 2022/09/28-17:19:20.104557) [db/compaction/compaction_job.cc:688] [default] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 2.0 rd, 2.0 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 10, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.104687 139935010756352 (Original Log Time 2022/09/28-17:19:20.104620) EVENT_LOG_v1 {"time_micros": 1664356760104589, "job": 3249, "event": "compaction_finished", "compaction_time_micros": 868, "compaction_time_cpu_micros": 734, "output_level": 1, "num_output_files": 1, "total_output_size": 1712, "num_input_records": 10, "num_output_records": 10, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.110356 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452023.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2022/09/28-17:19:20.110393 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760110384, "job": 3249, "event": "table_file_deletion", "file_number": 1452023}
2022/09/28-17:19:20.110464 139935010756352 [db/compaction/compaction_job.cc:1774] [__internal__] [JOB 3250] Compacting 1@1 files to L1, score 0.00
2022/09/28-17:19:20.110478 139935010756352 [db/compaction/compaction_job.cc:1778] [__internal__] Compaction start summary: Base version 3251 Base level 1, inputs: [1452024(3449B)]
2022/09/28-17:19:20.110512 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760110491, "job": 3250, "event": "compaction_started", "compaction_reason": "BottommostFiles", "files_L1": [1452024], "score": 0.000328922, "input_data_size": 3449}
2022/09/28-17:19:20.111565 139935010756352 [db/compaction/compaction_job.cc:1376] [__internal__] [JOB 3250] Generated table #1452026: 80 keys, 3449 bytes, temperature: kUnknown
2022/09/28-17:19:20.111711 139935010756352 EVENT_LOG_v1 {"time_micros": 1664356760111613, "cf_name": "__internal__", "job": 3250, "event": "table_file_creation", "file_number": 1452026, "file_size": 3449, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 2214, "index_size": 169, "index_partitions": 1, "top_level_index_size": 82, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 0, "raw_key_size": 6170, "raw_average_key_size": 77, "raw_value_size": 120, "raw_average_value_size": 1, "num_data_blocks": 1, "num_entries": 80, "num_filter_entries": 0, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "", "column_family_name": "__internal__", "column_family_id": 1, "comparator": "UserKeyComparator.ts", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; use_zstd_dict_trainer=1; ", "creation_time": 1664352757, "oldest_key_time": 0, "file_creation_time": 1664356760, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "ecbc7fee-23ee-4473-873f-6d92df77840f", "db_session_id": "66QZSRNEIIZAMC6PP0QG", "orig_file_number": 1452026, "seqno_to_time_mapping": "N/A", "rocksdb.timestamp_max": "E300000000000000", "rocksdb.timestamp_min": "0000000000000000"}}
2022/09/28-17:19:20.112412 139935010756352 (Original Log Time 2022/09/28-17:19:20.112007) [db/compaction/compaction_job.cc:1449] [__internal__] [JOB 3250] Compacted 1@1 files to L1 => 3449 bytes
2022/09/28-17:19:20.112422 139935010756352 (Original Log Time 2022/09/28-17:19:20.112315) [db/compaction/compaction_job.cc:688] [__internal__] compacted to: files[0 1 0 0 0 0 0] max score 0.00, MB/sec: 2.8 rd, 2.8 wr, level 1, files in(0, 1) out(1 +0 blob) MB in(0.0, 0.0 +0.0 blob) out(0.0 +0.0 blob), read-write-amplify(0.0) write-amplify(0.0) OK, records in: 80, records dropped: 0 output_compression: NoCompression
2022/09/28-17:19:20.112437 139935010756352 (Original Log Time 2022/09/28-17:19:20.112366) EVENT_LOG_v1 {"time_micros": 1664356760112337, "job": 3250, "event": "compaction_finished", "compaction_time_micros": 1248, "compaction_time_cpu_micros": 1101, "output_level": 1, "num_output_files": 1, "total_output_size": 3449, "num_input_records": 80, "num_output_records": 80, "num_subcompactions": 1, "output_compression": "NoCompression", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 0, 0, 0, 0, 0]}
2022/09/28-17:19:20.112554 139935010756352 [file/delete_scheduler.cc:77] Deleted file ./data/store0/3/0/db/1452024.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
@andoryu- andoryu- changed the title infinitely compact L1 to L1 infinite compaction loop Sep 28, 2022
@cbi42
Copy link
Member

cbi42 commented Sep 29, 2022 •
edited
Loading

Hi @andoryu-, thanks for reporting the issue. L1-L1 compaction can occur when RocksDB tries to clean up keys with different sequence number in the same file at bottommost level. I think in this case, keys with different sequence number are not dropped during compaction as they are not eligible for garbage collection (they are above full_history_ts_low) which caused the loop. @riversand963 it seems that user-fined timestamp is not compatible with this types of compactions (compaction reason kBottommostFiles) in that it might cause compaction loops, could you help confirm it?

@riversand963
Copy link
Contributor

Thanks @andoryu- for reporting and @cbi42 for the investigation.
I think @cbi42's analysis makes sense. We track the min and max timestamps of each file and can use this piece of information to better determine when to trigger this compaction and which files to include. The min/max timestamps used to be available in the file meta. They were added for pretty much the same reason, but were later removed due to concerns about memory consumption because the original implementation used two std::string for each file even if timestamp is not enabled. Nevertheless, they are still available in the properties block of the SST file.
Going forward, I think there are two possibilities:

  • add them back to file metadata in a more memory efficient way, or
  • opening the bottommost SST file and check the properties block

@cbi42 cbi42 self-assigned this Sep 29, 2022
@andoryu-
Copy link
Author

andoryu- commented Sep 30, 2022 •
edited
Loading

Thanks @cbi42 , @riversand963 for investigating this issue.
So if a snapshot keep userkey from being deleted in bottomost level file, it can end up in a compaction loop?
The default column family has udt disabled, and the other column family with udt enabled has called IncreaseFullHistoryTsLow(ULONG_MAX) at start up, which is sematically max udt value(currently the udt is decided by DB::GetLatestSequenceNumber()).
cf: default timestamp_size() == 0
cf: internal timestamp_size() == 8 is DB::GetLatestSequenceNumber()
So every userkey shall be eligible for garbage collection, except that current CompactionIterator decided to keep the "(6) timestamp is the largest one older than full_history_ts_low_"?
I suspect a snapshot is enough to prevent ikey from being deleted though? It seems that both cf:default and cf:internal end up in compaction loop. Another piece of context is that, just before writing to cf:internal with udt enabled, a snapshot of cf:default is taken and sent to another thread to asynchronously look up an old version of cf:default value to purge the old version in cf:internal to keep cf:internal consistent with cf:default, has also set allow_ingest_behind=true to prevent udt from being zeroed-out.

@cbi42
Copy link
Member

cbi42 commented Oct 2, 2022

Hi @andoryu- , thanks for the info. It seems to be an issue with allow_ingest_behind + kBottommostFiles compaction to me now, rather than udt. A key's sequence number is not zeroed out when allow_ingest_behind is enabled, and this caused the compaction loop (RocksDB keeps trying to compact the same file with reason kBottommostFiles).

@cbi42 cbi42 mentioned this issue Oct 3, 2022
Closed
facebook-github-bot pushed a commit that referenced this issue Oct 5, 2022
@cbi42 @facebook-github-bot
Ignore kBottommostFiles compaction logic when allow_ingest_behind (#1…
eca47fb 
…0767)

Summary:
fix for #10752 where RocksDB could be in an infinite compaction loop (with compaction reason kBottommostFiles)  if allow_ingest_behind is enabled and the bottommost level is unfilled.

Pull Request resolved: #10767

Test Plan: Added a unit test to reproduce the compaction loop.

Reviewed By: ajkr

Differential Revision: D40031861

Pulled By: ajkr

fbshipit-source-id: 71c4b02931fbe507a847632905404c9b8fa8c96b
@cbi42
Copy link
Member

cbi42 commented Oct 5, 2022

Fixed in #10767.

@cbi42 cbi42 closed this as completed Oct 5, 2022
riversand963 pushed a commit to riversand963/rocksdb that referenced this issue Oct 5, 2022
@cbi42 @riversand963
Ignore kBottommostFiles compaction logic when allow_ingest_behind (fa…
8e5d84c 
…cebook#10767)

Summary:
fix for facebook#10752 where RocksDB could be in an infinite compaction loop (with compaction reason kBottommostFiles)  if allow_ingest_behind is enabled and the bottommost level is unfilled.

Pull Request resolved: facebook#10767

Test Plan: Added a unit test to reproduce the compaction loop.

Reviewed By: ajkr

Differential Revision: D40031861

Pulled By: ajkr

fbshipit-source-id: 71c4b02931fbe507a847632905404c9b8fa8c96b
riversand963 pushed a commit that referenced this issue Oct 5, 2022
@cbi42 @riversand963
Ignore kBottommostFiles compaction logic when allow_ingest_behind (#1…
01cd296 
…0767)

Summary:
fix for #10752 where RocksDB could be in an infinite compaction loop (with compaction reason kBottommostFiles)  if allow_ingest_behind is enabled and the bottommost level is unfilled.

Pull Request resolved: #10767

Test Plan: Added a unit test to reproduce the compaction loop.

Reviewed By: ajkr

Differential Revision: D40031861

Pulled By: ajkr

fbshipit-source-id: 71c4b02931fbe507a847632905404c9b8fa8c96b
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@cbi42 cbi42

Labels
compaction
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@andoryu- @riversand963 @cbi42