Rocksdb: Occasional performance drop while the rocksdb growing with no stall or slow down log

[absolute8511]

While the rocksdb growing to larger than 4GB (above 40M keys), even write with low tps (only write less than 1000/s with 100bytes key value) can cost 1s~2s sometimes. It is too slow for write and no any stall or slow down logs. It appeared very rarely and the ssd disk io util is less than 1%.

Is this normal in rocksdb? I expected stable insert since the insert rate is low.

I am using the v5.8.8
My option for rocksdb is below:

2018/04/23-18:53:03.862430 7fafa97fb700                         Options.error_if_exists: 0
2018/04/23-18:53:03.862432 7fafa97fb700                       Options.create_if_missing: 0
2018/04/23-18:53:03.862434 7fafa97fb700                         Options.paranoid_checks: 1
2018/04/23-18:53:03.862436 7fafa97fb700                                     Options.env: 0x1928740
2018/04/23-18:53:03.862438 7fafa97fb700                                Options.info_log: 0x7faf6003f8a0
2018/04/23-18:53:03.862440 7fafa97fb700                Options.max_file_opening_threads: 16
2018/04/23-18:53:03.862442 7fafa97fb700                               Options.use_fsync: 0
2018/04/23-18:53:03.862443 7fafa97fb700                       Options.max_log_file_size: 33554432
2018/04/23-18:53:03.862445 7fafa97fb700                  Options.max_manifest_file_size: 33554432
2018/04/23-18:53:03.862447 7fafa97fb700                   Options.log_file_time_to_roll: 259200
2018/04/23-18:53:03.862450 7fafa97fb700                       Options.keep_log_file_num: 1000
2018/04/23-18:53:03.862452 7fafa97fb700                    Options.recycle_log_file_num: 0
2018/04/23-18:53:03.862454 7fafa97fb700                         Options.allow_fallocate: 1
2018/04/23-18:53:03.862456 7fafa97fb700                        Options.allow_mmap_reads: 0
2018/04/23-18:53:03.862457 7fafa97fb700                       Options.allow_mmap_writes: 0
2018/04/23-18:53:03.862459 7fafa97fb700                        Options.use_direct_reads: 0
2018/04/23-18:53:03.862461 7fafa97fb700                        Options.use_direct_io_for_flush_and_compaction: 0
2018/04/23-18:53:03.862463 7fafa97fb700          Options.create_missing_column_families: 0
2018/04/23-18:53:03.862465 7fafa97fb700                              Options.db_log_dir:
2018/04/23-18:53:03.862467 7fafa97fb700                                 Options.wal_dir: /data/test/rocksdb
2018/04/23-18:53:03.862469 7fafa97fb700                Options.table_cache_numshardbits: 6
2018/04/23-18:53:03.862471 7fafa97fb700                      Options.max_subcompactions: 1
2018/04/23-18:53:03.862473 7fafa97fb700                  Options.max_background_flushes: 2
2018/04/23-18:53:03.862475 7fafa97fb700                         Options.WAL_ttl_seconds: 0
2018/04/23-18:53:03.862477 7fafa97fb700                       Options.WAL_size_limit_MB: 0
2018/04/23-18:53:03.862479 7fafa97fb700             Options.manifest_preallocation_size: 4194304
2018/04/23-18:53:03.862481 7fafa97fb700                     Options.is_fd_close_on_exec: 1
2018/04/23-18:53:03.862482 7fafa97fb700                   Options.advise_random_on_open: 1
2018/04/23-18:53:03.862484 7fafa97fb700                    Options.db_write_buffer_size: 0
2018/04/23-18:53:03.862486 7fafa97fb700                    Options.write_buffer_manager: 0x7faf6003fc90
2018/04/23-18:53:03.862488 7fafa97fb700         Options.access_hint_on_compaction_start: 1
2018/04/23-18:53:03.862490 7fafa97fb700  Options.new_table_reader_for_compaction_inputs: 0
2018/04/23-18:53:03.862492 7fafa97fb700               Options.compaction_readahead_size: 0
2018/04/23-18:53:03.862494 7fafa97fb700           Options.random_access_max_buffer_size: 1048576
2018/04/23-18:53:03.862496 7fafa97fb700           Options.writable_file_max_buffer_size: 1048576
2018/04/23-18:53:03.862498 7fafa97fb700                      Options.use_adaptive_mutex: 0
2018/04/23-18:53:03.862516 7fafa97fb700                            Options.rate_limiter: (nil)
2018/04/23-18:53:03.862520 7fafa97fb700     Options.sst_file_manager.rate_bytes_per_sec: 0
2018/04/23-18:53:03.862522 7fafa97fb700                          Options.bytes_per_sync: 1048576
2018/04/23-18:53:03.862523 7fafa97fb700                      Options.wal_bytes_per_sync: 0
2018/04/23-18:53:03.862525 7fafa97fb700                       Options.wal_recovery_mode: 2
2018/04/23-18:53:03.862527 7fafa97fb700                  Options.enable_thread_tracking: 0
2018/04/23-18:53:03.862529 7fafa97fb700                  Options.enable_pipelined_write: 0
2018/04/23-18:53:03.862531 7fafa97fb700         Options.allow_concurrent_memtable_write: 1
2018/04/23-18:53:03.862532 7fafa97fb700      Options.enable_write_thread_adaptive_yield: 1
2018/04/23-18:53:03.862534 7fafa97fb700             Options.write_thread_max_yield_usec: 100
2018/04/23-18:53:03.862536 7fafa97fb700            Options.write_thread_slow_yield_usec: 3
2018/04/23-18:53:03.862537 7fafa97fb700                               Options.row_cache: None
2018/04/23-18:53:03.862539 7fafa97fb700                              Options.wal_filter: None
2018/04/23-18:53:03.862541 7fafa97fb700             Options.avoid_flush_during_recovery: 0
2018/04/23-18:53:03.862543 7fafa97fb700             Options.allow_ingest_behind: 0
2018/04/23-18:53:03.862544 7fafa97fb700             Options.concurrent_prepare: 0
2018/04/23-18:53:03.862546 7fafa97fb700             Options.manual_wal_flush: 0
2018/04/23-18:53:03.862548 7fafa97fb700             Options.max_background_jobs: 2
2018/04/23-18:53:03.862550 7fafa97fb700             Options.max_background_compactions: 2
2018/04/23-18:53:03.862551 7fafa97fb700             Options.avoid_flush_during_shutdown: 0
2018/04/23-18:53:03.862553 7fafa97fb700             Options.delayed_write_rate : 20000000
2018/04/23-18:53:03.862555 7fafa97fb700             Options.max_total_wal_size: 0
2018/04/23-18:53:03.862557 7fafa97fb700             Options.delete_obsolete_files_period_micros: 21600000000
2018/04/23-18:53:03.862559 7fafa97fb700                   Options.stats_dump_period_sec: 600
2018/04/23-18:53:03.862560 7fafa97fb700                          Options.max_open_files: -1
2018/04/23-18:53:03.862562 7fafa97fb700 Compression algorithms supported:
2018/04/23-18:53:03.862564 7fafa97fb700         Snappy supported: 1
2018/04/23-18:53:03.862566 7fafa97fb700         Zlib supported: 1
2018/04/23-18:53:03.862568 7fafa97fb700         Bzip supported: 1
2018/04/23-18:53:03.862569 7fafa97fb700         LZ4 supported: 0
2018/04/23-18:53:03.862571 7fafa97fb700         ZSTD supported: 0
2018/04/23-18:53:03.862573 7fafa97fb700 Fast CRC32 supported: 1

2018/04/23-18:53:03.863246 7fafa97fb700               Options.comparator: leveldb.BytewiseComparator
2018/04/23-18:53:03.863249 7fafa97fb700           Options.merge_operator: UInt64AddOperator
2018/04/23-18:53:03.863256 7fafa97fb700        Options.compaction_filter: None
2018/04/23-18:53:03.863258 7fafa97fb700        Options.compaction_filter_factory: None
2018/04/23-18:53:03.863260 7fafa97fb700         Options.memtable_factory: SkipListFactory
2018/04/23-18:53:03.863263 7fafa97fb700            Options.table_factory: BlockBasedTable
2018/04/23-18:53:03.863289 7fafa97fb700            table_factory options:   flush_block_policy_factory: FlushBlockBySizePolicyFactory (0x7faf9c002ce0)
  cache_index_and_filter_blocks: 0
  cache_index_and_filter_blocks_with_high_priority: 0
  pin_l0_filter_and_index_blocks_in_cache: 0
  index_type: 0
  hash_index_allow_collision: 1
  checksum: 1
  no_block_cache: 0
  block_cache: 0x2e60450
  block_cache_name: LRUCache
  block_cache_options:
    capacity : 20297594880
    num_shard_bits : 6
    strict_capacity_limit : 0
    high_pri_pool_ratio: 0.000
  block_cache_compressed: (nil)
  persistent_cache: (nil)
  block_size: 32768
  block_size_deviation: 10
  block_restart_interval: 16
  index_block_restart_interval: 1
  filter_policy: rocksdb.BuiltinBloomFilter
  whole_key_filtering: 1
  format_version: 2
2018/04/23-18:53:03.863327 7fafa97fb700        Options.write_buffer_size: 67108864
2018/04/23-18:53:03.863331 7fafa97fb700  Options.max_write_buffer_number: 6
2018/04/23-18:53:03.863334 7fafa97fb700        Options.compression[0]: NoCompression
2018/04/23-18:53:03.863336 7fafa97fb700        Options.compression[1]: NoCompression
2018/04/23-18:53:03.863338 7fafa97fb700        Options.compression[2]: NoCompression
2018/04/23-18:53:03.863340 7fafa97fb700        Options.compression[3]: Snappy
2018/04/23-18:53:03.863342 7fafa97fb700        Options.compression[4]: Snappy
2018/04/23-18:53:03.863344 7fafa97fb700        Options.compression[5]: Snappy
2018/04/23-18:53:03.863346 7fafa97fb700        Options.compression[6]: Snappy
2018/04/23-18:53:03.863348 7fafa97fb700                  Options.bottommost_compression: Disabled
2018/04/23-18:53:03.863351 7fafa97fb700       Options.prefix_extractor: rocksdb.FixedPrefix.3
2018/04/23-18:53:03.863353 7fafa97fb700   Options.memtable_insert_with_hint_prefix_extractor: nullptr
2018/04/23-18:53:03.863355 7fafa97fb700             Options.num_levels: 7
2018/04/23-18:53:03.863357 7fafa97fb700        Options.min_write_buffer_number_to_merge: 2
2018/04/23-18:53:03.863359 7fafa97fb700     Options.max_write_buffer_number_to_maintain: 0
2018/04/23-18:53:03.863360 7fafa97fb700            Options.compression_opts.window_bits: -14
2018/04/23-18:53:03.863362 7fafa97fb700                  Options.compression_opts.level: -1
2018/04/23-18:53:03.863364 7fafa97fb700               Options.compression_opts.strategy: 0
2018/04/23-18:53:03.863366 7fafa97fb700         Options.compression_opts.max_dict_bytes: 0
2018/04/23-18:53:03.863368 7fafa97fb700      Options.level0_file_num_compaction_trigger: 2
2018/04/23-18:53:03.863370 7fafa97fb700          Options.level0_slowdown_writes_trigger: 20
2018/04/23-18:53:03.863371 7fafa97fb700              Options.level0_stop_writes_trigger: 36
2018/04/23-18:53:03.863373 7fafa97fb700                   Options.target_file_size_base: 67108864
2018/04/23-18:53:03.863375 7fafa97fb700             Options.target_file_size_multiplier: 1
2018/04/23-18:53:03.863377 7fafa97fb700                Options.max_bytes_for_level_base: 268435456
2018/04/23-18:53:03.863379 7fafa97fb700 Options.level_compaction_dynamic_level_bytes: 0
2018/04/23-18:53:03.863383 7fafa97fb700          Options.max_bytes_for_level_multiplier: 10.000000
2018/04/23-18:53:03.863385 7fafa97fb700 Options.max_bytes_for_level_multiplier_addtl[0]: 1
2018/04/23-18:53:03.863387 7fafa97fb700 Options.max_bytes_for_level_multiplier_addtl[1]: 1
2018/04/23-18:53:03.863389 7fafa97fb700 Options.max_bytes_for_level_multiplier_addtl[2]: 1
2018/04/23-18:53:03.863390 7fafa97fb700 Options.max_bytes_for_level_multiplier_addtl[3]: 1
2018/04/23-18:53:03.863392 7fafa97fb700 Options.max_bytes_for_level_multiplier_addtl[4]: 1
2018/04/23-18:53:03.863394 7fafa97fb700 Options.max_bytes_for_level_multiplier_addtl[5]: 1
2018/04/23-18:53:03.863395 7fafa97fb700 Options.max_bytes_for_level_multiplier_addtl[6]: 1
2018/04/23-18:53:03.863397 7fafa97fb700       Options.max_sequential_skip_in_iterations: 8
2018/04/23-18:53:03.863399 7fafa97fb700                    Options.max_compaction_bytes: 1677721600
2018/04/23-18:53:03.863401 7fafa97fb700                        Options.arena_block_size: 8388608
2018/04/23-18:53:03.863403 7fafa97fb700   Options.soft_pending_compaction_bytes_limit: 68719476736
2018/04/23-18:53:03.863405 7fafa97fb700   Options.hard_pending_compaction_bytes_limit: 274877906944
2018/04/23-18:53:03.863407 7fafa97fb700       Options.rate_limit_delay_max_milliseconds: 100
2018/04/23-18:53:03.863401 7fafa97fb700                        Options.arena_block_size: 8388608
2018/04/23-18:53:03.863403 7fafa97fb700   Options.soft_pending_compaction_bytes_limit: 68719476736
2018/04/23-18:53:03.863405 7fafa97fb700   Options.hard_pending_compaction_bytes_limit: 274877906944
2018/04/23-18:53:03.863407 7fafa97fb700       Options.rate_limit_delay_max_milliseconds: 100
2018/04/23-18:53:03.863408 7fafa97fb700                Options.disable_auto_compactions: 0
2018/04/23-18:53:03.863411 7fafa97fb700                        Options.compaction_style: kCompactionStyleLevel
2018/04/23-18:53:03.863414 7fafa97fb700                          Options.compaction_pri: kByCompensatedSize
2018/04/23-18:53:03.863424 7fafa97fb700 Options.compaction_options_universal.size_ratio: 1
2018/04/23-18:53:03.863426 7fafa97fb700 Options.compaction_options_universal.min_merge_width: 2
2018/04/23-18:53:03.863428 7fafa97fb700 Options.compaction_options_universal.max_merge_width: 4294967295
2018/04/23-18:53:03.863430 7fafa97fb700 Options.compaction_options_universal.max_size_amplification_percent: 200
2018/04/23-18:53:03.863432 7fafa97fb700 Options.compaction_options_universal.compression_size_percent: -1
2018/04/23-18:53:03.863434 7fafa97fb700 Options.compaction_options_universal.stop_style: kCompactionStopStyleTotalSize
2018/04/23-18:53:03.863436 7fafa97fb700 Options.compaction_options_fifo.max_table_files_size: 1073741824
2018/04/23-18:53:03.863438 7fafa97fb700 Options.compaction_options_fifo.allow_compaction: 0
2018/04/23-18:53:03.863439 7fafa97fb700 Options.compaction_options_fifo.ttl: 0
2018/04/23-18:53:03.863442 7fafa97fb700                   Options.table_properties_collectors:
2018/04/23-18:53:03.863443 7fafa97fb700                   Options.inplace_update_support: 0
2018/04/23-18:53:03.863445 7fafa97fb700                 Options.inplace_update_num_locks: 10000
2018/04/23-18:53:03.863448 7fafa97fb700               Options.memtable_prefix_bloom_size_ratio: 0.100000
2018/04/23-18:53:03.863450 7fafa97fb700   Options.memtable_huge_page_size: 0
2018/04/23-18:53:03.863452 7fafa97fb700                           Options.bloom_locality: 0
2018/04/23-18:53:03.863453 7fafa97fb700                    Options.max_successive_merges: 0
2018/04/23-18:53:03.863455 7fafa97fb700                Options.optimize_filters_for_hits: 0
2018/04/23-18:53:03.863457 7fafa97fb700                Options.paranoid_file_checks: 0
2018/04/23-18:53:03.863458 7fafa97fb700                Options.force_consistency_checks: 0
2018/04/23-18:53:03.863460 7fafa97fb700                Options.report_bg_io_stats: 0

LOGS while slow

2018/04/23-22:23:10.067250 7fafa8d01700 EVENT_LOG_v1 {"time_micros": 1524493390067227, "job": 132, "event": "compaction_started", "files_L0": [3595, 3592], "files_L1": [3577], "sc
ore": 1, "input_data_size": 66608790}
2018/04/23-22:23:18.277642 7fafa8d01700 [db/compaction_job.cc:1144] [default] [JOB 132] Generated table #3596: 1319130 keys, 66608557 bytes
2018/04/23-22:23:18.277741 7fafa8d01700 EVENT_LOG_v1 {"time_micros": 1524493398277697, "cf_name": "default", "job": 132, "event": "table_file_creation", "file_number": 3596, "file
_size": 66608557, "table_properties": {"data_size": 64700875, "index_size": 125603, "filter_size": 1781026, "raw_key_size": 66190980, "raw_average_key_size": 50, "raw_value_size":
 43334211, "raw_average_value_size": 32, "num_data_blocks": 1979, "num_entries": 1319130, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands"
: "0"}}
2018/04/23-22:23:18.278462 7fafa8d01700 [db/compaction_job.cc:1211] [default] [JOB 132] Compacted 2@0 + 1@1 files to L1 => 66608557 bytes
2018/04/23-22:23:18.279433 7fafa8d01700 (Original Log Time 2018/04/23-22:23:18.279298) [db/compaction_job.cc:629] [default] compacted to: base level 1 max bytes base 268435456 fil
es[0 6 39 44 0 0 0] max score 0.96, MB/sec: 8.1 rd, 8.1 wr, level 1, files in(2, 1) out(1) MB in(50.7, 12.8) out(63.5), read-write-amplify(2.5) write-amplify(1.3) OK, records in:
1319131, records dropped: 1
2018/04/23-22:23:18.279442 7fafa8d01700 (Original Log Time 2018/04/23-22:23:18.279338) EVENT_LOG_v1 {"time_micros": 1524493398279319, "job": 132, "event": "compaction_finished", "
compaction_time_micros": 8211155, "output_level": 1, "num_output_files": 1, "total_output_size": 66608557, "num_input_records": 1319131, "num_output_records": 1319130, "num_subcom
pactions": 1, "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 6, 39, 44, 0, 0, 0]}
2018/04/23-22:23:18.296263 7fafa8d01700 EVENT_LOG_v1 {"time_micros": 1524493398296248, "job": 132, "event": "table_file_deletion", "file_number": 3595}
2018/04/23-22:23:18.314672 7fafa8d01700 EVENT_LOG_v1 {"time_micros": 1524493398314661, "job": 132, "event": "table_file_deletion", "file_number": 3592}
2018/04/23-22:23:18.314831 7fafa8d01700 EVENT_LOG_v1 {"time_micros": 1524493398314822, "job": 132, "event": "table_file_deletion", "file_number": 3577}
2018/04/23-22:24:42.069391 7faf72bfd700 [db/db_impl_write.cc:1183] [default] New memtable created with log file: #3597. Immutable memtables: 0.

...
slow write here cost about 1s
2018/04/23-22:25:03.021602  
...

2018/04/23-22:26:17.716746 7faf26ab1700 [db/db_impl_write.cc:1183] [default] New memtable created with log file: #3598. Immutable memtables: 1.
2018/04/23-22:26:17.716897 7faf935fe700 [db/db_impl_compaction_flush.cc:50] [JOB 133] Syncing log #3594
2018/04/23-22:26:17.716927 7faf935fe700 [db/db_impl_compaction_flush.cc:50] [JOB 133] Syncing log #3597
2018/04/23-22:26:17.720927 7faf935fe700 (Original Log Time 2018/04/23-22:26:17.716880) [db/db_impl_compaction_flush.cc:1239] Calling FlushMemTableToOutputFile with column family [
default], flush slots available 2, compaction slots available 1, flush slots scheduled 1, compaction slots scheduled 0
2018/04/23-22:26:17.720944 7faf935fe700 [db/flush_job.cc:264] [default] [JOB 133] Flushing memtable with next log file: 3597
2018/04/23-22:26:17.720955 7faf935fe700 [db/flush_job.cc:264] [default] [JOB 133] Flushing memtable with next log file: 3598
2018/04/23-22:26:17.721007 7faf935fe700 EVENT_LOG_v1 {"time_micros": 1524493577720987, "job": 133, "event": "flush_started", "num_memtables": 2, "num_entries": 1103072, "num_delet
es": 0, "memory_usage": 126673208}

...
...


** DB Stats **
Uptime(secs): 12989.4 total, 770.7 interval
Cumulative writes: 18M writes, 75M keys, 18M commit groups, 1.0 writes per commit group, ingest: 5.94 GB, 0.47 MB/s
Cumulative WAL: 18M writes, 0 syncs, 18754027.00 writes per sync, written: 5.94 GB, 0.47 MB/s
Cumulative stall: 00:00:0.000 H:M:S, 0.0 percent
Interval writes: 1103K writes, 4414K keys, 1103K commit groups, 1.0 writes per commit group, ingest: 357.83 MB, 0.46 MB/s
Interval WAL: 1103K writes, 0 syncs, 1103568.00 writes per sync, written: 0.35 MB, 0.46 MB/s
Interval stall: 00:00:0.000 H:M:S, 0.0 percent

** Compaction Stats [default] **
Level    Files   Size     Score Read(GB)  Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop
----------------------------------------------------------------------------------------------------------------------------------------------------------
  L0      2/0   50.76 MB   1.0      0.0     0.0      0.0       1.7      1.7       0.0   1.0      0.0     11.5       151        70    2.160       0      0
  L1      6/0   225.51 MB   0.9      3.4     1.7      1.8       3.3      1.6       0.0   2.0      8.9      8.7       393        34   11.570     65M  1315K
  L2     39/0    2.40 GB   1.0      5.8     1.2      4.6       5.6      1.0       0.3   4.5     10.6     10.1       565        16   35.342     87M  4603K
  L3     44/0    1.38 GB   0.1      2.0     1.0      1.0       1.0      0.0       0.0   1.0     17.6      8.9       117        10   11.722     80M    12M
 Sum     91/0    4.04 GB   0.0     11.3     3.9      7.3      11.6      4.3       0.3   6.8      9.4      9.7      1227       130    9.441    233M    18M
 Int      0/0    0.00 KB   0.0      1.0     0.4      0.6       1.0      0.3       0.0   9.8     10.1      9.4       106         9   11.791     29M  1522K
Uptime(secs): 12989.5 total, 770.7 interval
Flush(GB): cumulative 1.704, interval 0.099
AddFile(GB): cumulative 0.000, interval 0.000
AddFile(Total Files): cumulative 0, interval 0
AddFile(L0 Files): cumulative 0, interval 0
AddFile(Keys): cumulative 0, interval 0
Cumulative compaction: 11.65 GB write, 0.92 MB/s write, 11.26 GB read, 0.89 MB/s read, 1227.3 seconds
Interval compaction: 0.97 GB write, 1.29 MB/s write, 1.05 GB read, 1.39 MB/s read, 106.1 seconds
Stalls(count): 0 level0_slowdown, 0 level0_slowdown_with_compaction, 0 level0_numfiles, 0 level0_numfiles_with_compaction, 0 stop for pending_compaction_bytes, 0 slowdown for pending_compaction_bytes, 0 memtable_compaction, 0 memtable_slowdown, interval 0 total count

Thanks for any advice.

[absolute8511]

Another performance issue is: If there are some small DeleteRange (each delete range about 10~100 keys) or many Deleted keys in the iterator range, it may impact the iterator performance greatly.

Is there any way we can improve the iterator with some deleted keys?

[anand1976]

Writes taking long at low write tps is not normal for RocksDB. Can you profile the system to see what could be causing it? Is there a CPU spike or disk latency spike?

Regarding your question about iterator performance, you can try to tune ReadOptions::max_skippable_internal_keys and/or ReadOptions::ignore_range_deletions. Keep in mind that changing these will alter the iteration results though.

Cc: @ajkr

[absolute8511]

Thanks for your advice for the iterator. @anand1976 I will see if it will be ok to ignore some deleted keys.

from top and iostat, I saw both the cpu and disk usage is low. None of 24 cpu cores usage is higher than 30% and iowait is below 0.1ms. And I tried to add some slow log in rocksdb DBImpl::WriteImpl and most time cost in writing memtable.

And what is weird is after restarting the rocksdb, it can write fast for a while and after a while, it will again get some slow write that cost 1~2s.

Is there any method that I can narrow down the problem?

[ajkr]

Want to try using PerfContext to get a breakdown of where time is spent on the write path? Maybe enable it for every query but only output it for slow queries. Also it'd be best if you build against RocksDB master branch since it contains a recent commit (https://github.com/facebook/rocksdb/commit/affe01b0d53303ea8869b17a8ab85d77931810a2) that makes write path timers more precise.

[ajkr]

BTW we have a wiki page explaining how to use PerfContext: https://github.com/facebook/rocksdb/wiki/Perf-Context-and-IO-Stats-Context

[absolute8511]

@ajkr I added some logs in DBImpl::WriteImpl and found the slow is in write_memtable_time.

I will try using PerfContext to get details report later, Thanks.

[absolute8511]

Does delete keys hurt the write latency (with low throughput) if no background compaction job running? If so, will prefix_extractor be used to optimize write path?

[absolute8511]

@ajkr @anand1976
I did a perf at low write tps and get detail report as below, and found slow write cost in write_memtable_time mostly, and write_scheduling_flushes_compactions_time sometimes.

2018/05/01-08:25:40.736142 7f20fb1c9700 [WARN] [db/db_impl_write.cc:411] 548129637744361 slow write cost 505654708, user_key_comparison_count = 6, write_wal_time = 102520, write_pre_and_post_process_time = 5015, write_memtable_time = 9079, write_scheduling_flushes_compactions_time = 505535633, db_mutex_lock_nanos = 406,
2018/05/01-08:28:02.271351 7f20fb1c9700 [db/db_impl_write.cc:1377] [default] New memtable created with log file: #2561. Immutable memtables: 1.

2018/05/01-08:40:06.822457 7f2096bfd700 [db/db_impl_write.cc:1377] [default] New memtable created with log file: #2574. Immutable memtables: 0.
2018/05/01-08:40:13.098206 7f2066bfd700 [WARN] [db/db_impl_write.cc:411] 549001600794754 slow write cost 904652562, user_key_comparison_count = 68, write_wal_time = 8490, write_pre_and_post_process_time = 1717, write_memtable_time = 904640225, write_scheduling_flushes_compactions_time = 201, db_mutex_lock_nanos = 116,
2018/05/01-08:40:43.861398 7f207e1fc700 [WARN] [db/db_impl_write.cc:411] 549032270663124 slow write cost 997991090, user_key_comparison_count = 102, write_wal_time = 6751, write_pre_and_post_process_time = 1370, write_memtable_time = 997981056, write_scheduling_flushes_compactions_time = 100, db_mutex_lock_nanos = 220,
2018/05/01-08:42:37.863893 7f20701f4700 [db/db_impl_write.cc:1377] [default] New memtable created with log file: #2575. Immutable memtables: 1.

io stats

Time           ------------------------------------------sdb-------------------------------------------
Time            rrqms   wrqms      rs      ws   rsecs   wsecs  rqsize  qusize   await   svctm    util
01/05/18-08:10   0.00    0.00   12.34    7.3K  309.51   29.1K    4.03    3.00    0.45    0.01    5.95
01/05/18-08:15   0.00    0.00   46.20    5.4K    3.4K   21.8K    4.58    2.00    0.42    0.01    4.55
01/05/18-08:20   0.00    0.00   21.08   10.9K    3.8K   43.7K    4.34    5.00    0.50    0.01    9.34
01/05/18-08:25   0.00    0.00    3.01    3.3K   17.36   13.2K    4.00    1.00    0.42    0.01    2.58
01/05/18-08:30   0.00    0.00    6.90    3.0K   42.51   12.0K    4.00    1.00    0.47    0.01    2.50
01/05/18-08:35   0.00    0.00    6.89    2.8K   42.32   11.2K    4.01    1.00    0.40    0.01    2.37
01/05/18-08:40   0.00    0.00   12.31    8.7K    1.1K   34.8K    4.12    4.00    0.51    0.01    7.10
01/05/18-08:45   0.00    0.00    4.46    5.1K   26.87   20.2K    4.00    2.00    0.44    0.01    4.19
01/05/18-08:50   0.00    0.00    6.84    8.8K  161.29   35.3K    4.01    4.00    0.46    0.01    7.26
01/05/18-08:55   0.00    0.00    7.46    3.2K   45.32   12.6K    4.00    1.00    0.46    0.01    2.82

cpu stats

Time           ---------------------------cpu--------------------------
Time             user     sys    wait    hirq    sirq    util    diff
01/05/18-08:05  12.75    3.63    0.02    0.00    0.84   17.21    0.00
01/05/18-08:10  13.63    3.70    0.03    0.00    0.93   18.26    0.00
01/05/18-08:15  12.89    3.99    0.02    0.00    0.88   17.76    0.00
01/05/18-08:20  14.26    4.17    0.05    0.00    1.03   19.47    0.00
01/05/18-08:25  12.73    3.52    0.02    0.00    0.84   17.09    0.00
01/05/18-08:30  12.77    3.54    0.02    0.00    0.84   17.15    0.00
01/05/18-08:35  12.60    3.52    0.02    0.00    0.83   16.94    0.00
01/05/18-08:40  13.89    4.11    0.04    0.00    0.95   18.95    0.00
01/05/18-08:45  12.59    3.98    0.02    0.00    0.84   17.41    0.00
01/05/18-08:50  13.56    4.23    0.03    0.00    0.94   18.73    0.00
01/05/18-08:55  12.73    3.57    0.02    0.00    0.84   17.14    0.00
01/05/18-09:00  13.06    3.44    0.02    0.00    0.86   17.36    0.00
01/05/18-09:05  13.08    3.47    0.02    0.00    0.85   17.40    0.00
01/05/18-09:10  13.65    3.59    0.03    0.00    0.91   18.15    0.00
01/05/18-09:15  13.93    3.66    0.03    0.00    0.92   18.51    0.00

And I also found rarely slow read as below

2018/05/01-08:20:43.462290 7f20affff700 [WARN] [db/db_impl.cc:1118] 547832089998760 slow read cost 779521997, user_key_comparison_count = 96, block_read_count = 1, block_read_byte = 32691, block_read_time = 62146, block_decompress_time = 307, get_read_bytes = 9, get_snapshot_time = 277, get_from_memtable_time = 5773, get_from_memtable_count = 2, get_post_process_time = 2783, get_from_output_files_time = 779511742, new_table_block_iter_nanos = 779492479, block_seek_nanos = 5352, bloom_memtable_hit_count = 2, bloom_sst_hit_count = 1,
2018/05/01-08:21:37.117412 7f20661fc700 [db/db_impl_write.cc:1377] [default] New memtable created with log file: #2348. Immutable memtables: 1.

and

2018/05/01-08:38:08.479072 7f2064dfa700 [WARN] [db/db_impl.cc:1118] 548877363952797 slow read cost 522351859, user_key_comparison_count = 64, block_read_count = 1, block_read_byte = 32697, block_read_time = 45330, block_decompress_time = 150, get_read_bytes = 9, get_snapshot_time = 291, get_from_memtable_time = 2940, get_from_memtable_count = 1, get_post_process_time = 2170, get_from_output_files_time = 522345129, new_table_block_iter_nanos = 522326361, block_seek_nanos = 6303, bloom_memtable_hit_count = 1, bloom_sst_hit_count = 1, bloom_sst_miss_count = 1,
2018/05/01-08:38:18.628447 7f206e240700 [db/db_impl_write.cc:1377] [default] New memtable created with log file: #2364. Immutable memtables: 0.
2018/05/01-08:40:27.134017 7f2070bf5700 [WARN] [db/db_impl.cc:1118] 549016023061277 slow read cost 518162496, user_key_comparison_count = 98, block_read_count = 1, block_read_byte = 32689, block_read_time = 56465, block_decompress_time = 320, get_read_bytes = 9, get_snapshot_time = 237, get_from_memtable_time = 4969, get_from_memtable_count = 2, get_post_process_time = 2560, get_from_output_files_time = 518153455, new_table_block_iter_nanos = 518130182, block_seek_nanos = 8821, bloom_memtable_hit_count = 2, bloom_sst_hit_count = 1, bloom_sst_miss_count = 1,

Another slow case is the key for uint64add_merge_operator may get very slow in point lookup (I am using this key as a counter), however in this case the v5.8.8 seems very fast, I think there is something wrong in the master branch handling this case. Slow log as below:

2018/05/01-21:56:56.938122 7f48c57fb700 [WARN] [db/db_impl.cc:1118] 596803063949337 slow read cost 3281411612, user_key_comparison_count = 33, block_cache_hit_count = 1, get_read_
bytes = 8, get_snapshot_time = 410, get_from_memtable_time = 3273141247, get_from_memtable_count = 1, get_post_process_time = 3303, get_from_output_files_time = 8263626, merge_ope
rator_time_nanos = 8235844, new_table_block_iter_nanos = 5187, block_seek_nanos = 3883, bloom_memtable_hit_count = 1, bloom_sst_hit_count = 1,
2018/05/01-21:57:05.327630 7f499ca99700 [WARN] [db/db_impl.cc:1118] 596811353136496 slow read cost 3381739373, user_key_comparison_count = 33, block_cache_hit_count = 1, get_read_bytes = 8, get_snapshot_time = 380, get_from_memtable_time = 3371644290, get_from_memtable_count = 1, get_post_process_time = 3039, get_from_output_files_time = 10087701, merge_operator_time_nanos = 10058153, new_table_block_iter_nanos = 6042, block_seek_nanos = 3714, bloom_memtable_hit_count = 1, bloom_sst_hit_count = 1,

[absolute8511]

@ajkr @anand1976

Any more details need to investigate into this? Maybe add more perf stats in memtable insert.

[anand1976]

@absolute8511 Sorry for the delay. We also have IOStatsContext that can give more stats in the file IO path - include/rocksdb/iostats_context.h. Can you use capture that when the slow write happens?

[absolute8511]

@anand1976
As the PerfContext showed most time cost in write_memtable_time. I thought the memtable write will not do the io related operation. If necessary I will capture stats with IOStatsContext.

[anand1976]

@absolute8511 You're right, since the high write cost is in write_memtable_time the IOStatsContext may not help. Cc @maysamyabandeh and @yiwu-arbug for advice on how to debug this further.

[ajkr]

I suspect the slowness in reading keys with uint64add_merge_operator is the same issue as #3865. The blame commit is 93c2b91740afa1667963e3c020b354ae5d6705eb, which was introduced in 5.9, so it aligns with your timeline of when it became slow. cc @sagar0

[ajkr]

You could try setting max_successive_merges to something like 1000.

Also is it possible to run the perf record -g -p <your process's pid> when there are slow writes happening? And show us the output of perf report -g? I can't think of anything that slow to account for the high write_memtable_time.

[absolute8511]

@ajkr
I will try max_successive_merges and see if any improvement. I will try perf record -g -p <your process's pid> to get more details, but the slow is rare and I will try if I can get the perf data while slow writes happening.

[tulshiba]

@absolute8511 One way to narrow down the issue is to add new counters/timers to perf context structure. And then you can make add these new timers/counters around various functions in the write path. That way you exactly know which phase during the write path is adding to high latency.

[absolute8511]

@ajkr
I did some test and seems setting max_successive_merges to 1000 solved this latency.

@tulshiba Is any suggestion where I could add new counters/timers to narrow down write_memtable_time cost?

Another tip I found useful for latency improvement is to disable transparent huge pages (THP) in CentOS. As this link advised, THP is not recommended for database workloads. It can be disabled as below

# echo never > /sys/kernel/mm/redhat_transparent_hugepage/enabled
# echo never > /sys/kernel/mm/redhat_transparent_hugepage/defrag

[yuwenlong123]

how to resolve the cost in memtable write at end? @absolute8511

[absolute8511]

@yuwenlong123

The cost in write_memtable_time could be resolved by Disable THP.

[anand1976]

@absolute8511 I know its been a while. Did disabling THP resolve the high write_memtable_time?

[absolute8511]

@anand1976 Yeah, it is resolved.

[anand1976]

Thanks. I'll close this issue.

[lintanghui]

same problem with write_memtable_time cost a lot of time. after set THP, it cannot resolve yet