Hi all,
I'm trying to get an better understanding regarding the "latency spikes" we see
on *every* SSD-OSD (it may very well be on HDD's as well but to be honest I
haven't bothered looking there since they are of no interest at the moment).
Anyway, we are running a cluster with version 'ceph version 12.2.8-89.el7cp
(2f66ab2fa63b2879913db6d6cf314572a83fd1f0) luminous (stable)' and recently
upgraded all our OSD's to bluestore. Unfortunately the way the upgrade was
done, earlier graphs / historical data of the cluster was lost (something about
when switching from collectd to the promethius approach) - none the less, I
can't say if the spikes were there before switching to bluestore.
I seem to have narrowed down the spikes to when the OSD's are doing
'compaction_started' and 'compaction_finished'. During that time (which of
course is different on every OSD) we see spikes in the area between ~20ms - ~80
ms. Which seems worrying. Looking at the average latency it varies between
~0.2ms - ~9ms.
I've tried to understand the underlying mechanism's involved here and which
parameters to tune, but I find it extremely hard.
The current config of an OSD regarding bluestore looks like the following,
$ > ceph -n osd.88 --show-config | grep bluestore
debug_bluestore = 1/5
bluestore_2q_cache_kin_ratio = 0.500000
bluestore_2q_cache_kout_ratio = 0.500000
bluestore_allocator = stupid
bluestore_bitmapallocator_blocks_per_zone = 1024
bluestore_bitmapallocator_span_size = 1024
bluestore_blobid_prealloc = 10240
bluestore_block_create = true
bluestore_block_db_create = false
bluestore_block_db_path =
bluestore_block_db_size = 0
bluestore_block_path =
bluestore_block_preallocate_file = false
bluestore_block_size = 10737418240
bluestore_block_wal_create = false
bluestore_block_wal_path =
bluestore_block_wal_size = 100663296
bluestore_bluefs = true
bluestore_bluefs_balance_interval = 1.000000
bluestore_bluefs_env_mirror = false
bluestore_bluefs_gift_ratio = 0.020000
bluestore_bluefs_max_ratio = 0.900000
bluestore_bluefs_min = 1073741824
bluestore_bluefs_min_free = 1073741824
bluestore_bluefs_min_ratio = 0.020000
bluestore_bluefs_reclaim_ratio = 0.200000
bluestore_cache_autotune = true
bluestore_cache_autotune_chunk_size = 33554432
bluestore_cache_autotune_interval = 5.000000
bluestore_cache_kv_ratio = 0.400000
bluestore_cache_meta_ratio = 0.400000
bluestore_cache_size = 0
bluestore_cache_size_hdd = 1073741824
bluestore_cache_size_ssd = 3221225472
bluestore_cache_trim_interval = 0.050000
bluestore_cache_trim_max_skip_pinned = 64
bluestore_cache_type = 2q
bluestore_clone_cow = true
bluestore_compression_algorithm = snappy
bluestore_compression_max_blob_size = 0
bluestore_compression_max_blob_size_hdd = 524288
bluestore_compression_max_blob_size_ssd = 65536
bluestore_compression_min_blob_size = 0
bluestore_compression_min_blob_size_hdd = 131072
bluestore_compression_min_blob_size_ssd = 8192
bluestore_compression_mode = none
bluestore_compression_required_ratio = 0.875000
bluestore_csum_max_block = 65536
bluestore_csum_min_block = 4096
bluestore_csum_type = crc32c
bluestore_debug_freelist = false
bluestore_debug_fsck_abort = false
bluestore_debug_inject_read_err = false
bluestore_debug_misc = false
bluestore_debug_no_reuse_blocks = false
bluestore_debug_omit_block_device_write = false
bluestore_debug_omit_kv_commit = false
bluestore_debug_permit_any_bdev_label = false
bluestore_debug_prefill = 0.000000
bluestore_debug_prefragment_max = 1048576
bluestore_debug_random_read_err = 0.000000
bluestore_debug_randomize_serial_transaction = 0
bluestore_debug_small_allocations = 0
bluestore_default_buffered_read = true
bluestore_default_buffered_write = false
bluestore_deferred_batch_ops = 0
bluestore_deferred_batch_ops_hdd = 64
bluestore_deferred_batch_ops_ssd = 16
bluestore_extent_map_inline_shard_prealloc_size = 256
bluestore_extent_map_shard_max_size = 1200
bluestore_extent_map_shard_min_size = 150
bluestore_extent_map_shard_target_size = 500
bluestore_extent_map_shard_target_size_slop = 0.200000
bluestore_freelist_blocks_per_key = 128
bluestore_fsck_on_mkfs = true
bluestore_fsck_on_mkfs_deep = false
bluestore_fsck_on_mount = false
bluestore_fsck_on_mount_deep = true
bluestore_fsck_on_umount = false
bluestore_fsck_on_umount_deep = true
bluestore_gc_enable_blob_threshold = 0
bluestore_gc_enable_total_threshold = 0
bluestore_kvbackend = rocksdb
bluestore_max_alloc_size = 0
bluestore_max_blob_size = 0
bluestore_max_blob_size_hdd = 524288
bluestore_max_blob_size_ssd = 65536
bluestore_max_deferred_txc = 32
bluestore_min_alloc_size = 0
bluestore_min_alloc_size_hdd = 65536
bluestore_min_alloc_size_ssd = 16384
bluestore_nid_prealloc = 1024
bluestore_prefer_deferred_size = 0
bluestore_prefer_deferred_size_hdd = 32768
bluestore_prefer_deferred_size_ssd = 0
bluestore_rocksdb_options =
compression=kNoCompression,max_write_buffer_number=4,min_write_buffer_number_to_merge=1,recycle_log_file_num=4,write_buffer_size=268435456,writable_file_max_buffer_size=0,compaction_readahead_size=2097152
bluestore_shard_finishers = false
bluestore_spdk_coremask = 0x3
bluestore_spdk_max_io_completion = 0
bluestore_spdk_mem = 512
bluestore_sync_submit_transaction = false
bluestore_throttle_bytes = 67108864
bluestore_throttle_cost_per_io = 0
bluestore_throttle_cost_per_io_hdd = 670000
bluestore_throttle_cost_per_io_ssd = 4000
bluestore_throttle_deferred_bytes = 134217728
mon_debug_no_require_bluestore_for_ec_overwrites = false
The logs from a specific OSD during the timeperiod where one "spike occurs"
looks like this (the graph suggests the time period around 2019-04-07 04:08),
= = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =
2019-04-07 04:01:33.393575 7fba248c4700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_write.cc:684] reusing
log 17652 from recycle list
2019-04-07 04:01:33.393726 7fba248c4700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_write.cc:725]
[default] New memtable created with log file: #17656. Immutable memtables: 0.
2019-04-07 04:01:33.394191 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:01:33.393750)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_compaction_flush.cc:1158]
Calling FlushMemTableToOutputFile with column family [default], flush slots
available 1, compaction slots allowed 1, compaction slots scheduled 1
2019-04-07 04:01:33.394200 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/flush_job.cc:264] [default]
[JOB 6774] Flushing memtable with next log file: 17656
2019-04-07 04:01:33.394211 7fba0e097700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602493394204, "job": 6774, "event": "flush_started",
"num_memtables": 1, "num_entries": 328448, "num_deletes": 72449,
"memory_usage": 260051496}
2019-04-07 04:01:33.394213 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/flush_job.cc:293] [default]
[JOB 6774] Level-0 flush table #17657: started
2019-04-07 04:01:33.540589 7fba0e097700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602493540576, "cf_name": "default", "job": 6774, "event":
"table_file_creation", "file_number": 17657, "file_size": 12268280,
"table_properties": {"data_size": 11712643, "index_size": 178205,
"filter_size": 376443, "raw_key_size": 7426084, "raw_average_key_size": 53,
"raw_value_size": 9209707, "raw_average_value_size": 65, "num_data_blocks":
2909, "num_entries": 139996, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "72424", "kMergeOperands":
"2671"}}
2019-04-07 04:01:33.540599 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/flush_job.cc:319] [default]
[JOB 6774] Level-0 flush table #17657: 12268280 bytes OK
2019-04-07 04:01:33.541237 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_files.cc:242] adding
log 17654 to recycle list
2019-04-07 04:01:33.541243 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:01:33.540606)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/memtable_list.cc:360]
[default] Level-0 commit table #17657 started
2019-04-07 04:01:33.541246 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:01:33.541206)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/memtable_list.cc:383]
[default] Level-0 commit table #17657: memtable #1 done
2019-04-07 04:01:33.541248 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:01:33.541216) EVENT_LOG_v1 {"time_micros": 1554602493541211,
"job": 6774, "event": "flush_finished", "lsm_state": [3, 1, 9, 0, 0, 0, 0],
"immutable_memtables": 0}
2019-04-07 04:01:33.541250 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:01:33.541230)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_compaction_flush.cc:132]
[default] Level summary: base level 1 max bytes base 268435456 files[3 1 9 0 0
0 0] max score 0.75
2019-04-07 04:01:33.541255 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_files.cc:388] [JOB
6774] Try to delete WAL files size 253619970, prev total WAL file size
253778896, number of live WAL files 2.
2019-04-07 04:07:38.822080 7fba248c4700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_write.cc:684] reusing
log 17654 from recycle list
2019-04-07 04:07:38.822307 7fba248c4700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_write.cc:725]
[default] New memtable created with log file: #17658. Immutable memtables: 0.
2019-04-07 04:07:38.823004 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:07:38.822334)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_compaction_flush.cc:1158]
Calling FlushMemTableToOutputFile with column family [default], flush slots
available 1, compaction slots allowed 1, compaction slots scheduled 1
2019-04-07 04:07:38.823012 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/flush_job.cc:264] [default]
[JOB 6775] Flushing memtable with next log file: 17658
2019-04-07 04:07:38.823023 7fba0e097700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602858823017, "job": 6775, "event": "flush_started",
"num_memtables": 1, "num_entries": 319003, "num_deletes": 70609,
"memory_usage": 260049200}
2019-04-07 04:07:38.823037 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/flush_job.cc:293] [default]
[JOB 6775] Level-0 flush table #17659: started
2019-04-07 04:07:38.972070 7fba0e097700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602858972057, "cf_name": "default", "job": 6775, "event":
"table_file_creation", "file_number": 17659, "file_size": 10264801,
"table_properties": {"data_size": 9777447, "index_size": 148893, "filter_size":
337472, "raw_key_size": 6697519, "raw_average_key_size": 53, "raw_value_size":
7537516, "raw_average_value_size": 59, "num_data_blocks": 2436, "num_entries":
126115, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys":
"70615", "kMergeOperands": "1900"}}
2019-04-07 04:07:38.972080 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/flush_job.cc:319] [default]
[JOB 6775] Level-0 flush table #17659: 10264801 bytes OK
2019-04-07 04:07:38.972562 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_files.cc:242] adding
log 17656 to recycle list
2019-04-07 04:07:38.972570 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:07:38.972087)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/memtable_list.cc:360]
[default] Level-0 commit table #17659 started
2019-04-07 04:07:38.972574 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:07:38.972525)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/memtable_list.cc:383]
[default] Level-0 commit table #17659: memtable #1 done
2019-04-07 04:07:38.972576 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:07:38.972536) EVENT_LOG_v1 {"time_micros": 1554602858972532,
"job": 6775, "event": "flush_finished", "lsm_state": [4, 1, 9, 0, 0, 0, 0],
"immutable_memtables": 0}
2019-04-07 04:07:38.972578 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:07:38.972555)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_compaction_flush.cc:132]
[default] Level summary: base level 1 max bytes base 268435456 files[4 1 9 0 0
0 0] max score 1.00
2019-04-07 04:07:38.972583 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_files.cc:388] [JOB
6775] Try to delete WAL files size 253805042, prev total WAL file size
253877756, number of live WAL files 2.
2019-04-07 04:07:38.972728 7fba230c1700 3 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl.cc:447] -------
DUMPING STATS -------
2019-04-07 04:07:38.972734 7fba230c1700 3 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl.cc:448]
** DB Stats **
Uptime(secs): 1155670.4 total, 1463.9 interval
Cumulative writes: 332M writes, 1661M keys, 332M commit groups, 1.0 writes per
commit group, ingest: 1194.88 GB, 1.06 MB/s
Cumulative WAL: 332M writes, 150M syncs, 2.21 writes per sync, written: 1194.88
GB, 1.06 MB/s
Cumulative stall: 00:00:0.000 H:M:S, 0.0 percent
Interval writes: 277K writes, 1291K keys, 277K commit groups, 1.0 writes per
commit group, ingest: 967.91 MB, 0.66 MB/s
Interval WAL: 277K writes, 135K syncs, 2.06 writes per sync, written: 0.95 MB,
0.66 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 4/0 41.90 MB 1.0 0.0 0.0 0.0 54.6 54.6
0.0 1.0 0.0 73.3 763 5061 0.151 0 0
L1 1/0 26.39 MB 0.7 75.9 54.6 21.3 37.3 16.0
0.0 0.7 75.4 37.1 1030 1265 0.814 1073M 221M
L2 9/0 542.29 MB 0.2 234.9 16.0 218.9 219.0 0.1
0.0 13.7 104.5 97.4 2302 448 5.139 1202M 411M
Sum 14/0 610.57 MB 0.0 310.8 70.6 240.2 310.9 70.8
0.0 5.7 77.7 77.7 4096 6774 0.605 2275M 633M
Int 0/0 0.00 KB 0.0 0.1 0.0 0.0 0.1 0.0
0.0 1.6 46.4 53.7 1 5 0.254 889K 206K
Uptime(secs): 1155670.4 total, 1155670.4 interval
Flush(GB): cumulative 54.628, interval 0.041
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: 310.92 GB write, 0.28 MB/s write, 310.78 GB read, 0.28
MB/s read, 4095.7 seconds
Interval compaction: 0.07 GB write, 0.00 MB/s write, 0.06 GB read, 0.00 MB/s
read, 1.3 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
** File Read Latency Histogram By Level [default] **
** 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 4/0 41.90 MB 1.0 0.0 0.0 0.0 54.6 54.6
0.0 1.0 0.0 73.3 763 5061 0.151 0 0
L1 1/0 26.39 MB 0.7 75.9 54.6 21.3 37.3 16.0
0.0 0.7 75.4 37.1 1030 1265 0.814 1073M 221M
L2 9/0 542.29 MB 0.2 234.9 16.0 218.9 219.0 0.1
0.0 13.7 104.5 97.4 2302 448 5.139 1202M 411M
Sum 14/0 610.57 MB 0.0 310.8 70.6 240.2 310.9 70.8
0.0 5.7 77.7 77.7 4096 6774 0.605 2275M 633M
Int 0/0 0.00 KB 0.0 0.0 0.0 0.0 0.0 0.0
0.0 0.0 0.0 0.0 0 0 0.000 0 0
Uptime(secs): 1155670.4 total, 1155670.4 interval
Flush(GB): cumulative 54.628, interval 0.000
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: 310.92 GB write, 0.28 MB/s write, 310.78 GB read, 0.28
MB/s read, 4095.7 seconds
Interval compaction: 0.00 GB write, 0.00 MB/s write, 0.00 GB read, 0.00 MB/s
read, 0.0 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
** File Read Latency Histogram By Level [default] **
2019-04-07 04:07:38.972770 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1403]
[default] [JOB 6776] Compacting 4@0 + 1@1 files to L1, score 1.00
2019-04-07 04:07:38.972777 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1407]
[default] Compaction start summary: Base version 6775 Base level 0, inputs:
[17659(10024KB) 17657(11MB) 17655(10096KB) 17653(10MB)], [17651(26MB)]
2019-04-07 04:07:38.972795 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602858972780, "job": 6776, "event": "compaction_started",
"files_L0": [17659, 17657, 17655, 17653], "files_L1": [17651], "score": 1,
"input_data_size": 71601163}
2019-04-07 04:07:39.921386 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6776] Generated table #17660: 967828 keys, 33787488 bytes
2019-04-07 04:07:39.921410 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602859921397, "cf_name": "default", "job": 6776, "event":
"table_file_creation", "file_number": 17660, "file_size": 33787488,
"table_properties": {"data_size": 30798279, "index_size": 498454,
"filter_size": 2489763, "raw_key_size": 50167310, "raw_average_key_size": 51,
"raw_value_size": 15631664, "raw_average_value_size": 16, "num_data_blocks":
7644, "num_entries": 967828, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "849562", "kMergeOperands":
"16907"}}
2019-04-07 04:07:39.921478 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1173]
[default] [JOB 6776] Compacted 4@0 + 1@1 files to L1 => 33787488 bytes
2019-04-07 04:07:39.922027 7fba230c1700 4 rocksdb: (Original Log Time
2019/04/07-04:07:39.921926)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:621]
[default] compacted to: base level 1 max bytes base 268435456 files[0 1 9 0 0 0
0] max score 1.15, MB/sec: 75.5 rd, 35.6 wr, level 1, files in(4, 1) out(1) MB
in(41.9, 26.4) out(32.2), read-write-amplify(2.4) write-amplify(0.8) OK,
records in: 1203386, records dropped: 229905
2019-04-07 04:07:39.922035 7fba230c1700 4 rocksdb: (Original Log Time
2019/04/07-04:07:39.921943) EVENT_LOG_v1 {"time_micros": 1554602859921935,
"job": 6776, "event": "compaction_finished", "compaction_time_micros": 948672,
"output_level": 1, "num_output_files": 1, "total_output_size": 33787488,
"num_input_records": 1197733, "num_output_records": 967828,
"num_subcompactions": 1, "num_single_delete_mismatches": 0,
"num_single_delete_fallthrough": 0, "lsm_state": [0, 1, 9, 0, 0, 0, 0]}
2019-04-07 04:07:39.922062 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602859922059, "job": 6776, "event": "table_file_deletion",
"file_number": 17659}
2019-04-07 04:07:39.922073 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602859922072, "job": 6776, "event": "table_file_deletion",
"file_number": 17657}
2019-04-07 04:07:39.922082 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602859922080, "job": 6776, "event": "table_file_deletion",
"file_number": 17655}
2019-04-07 04:07:39.922089 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602859922088, "job": 6776, "event": "table_file_deletion",
"file_number": 17653}
2019-04-07 04:07:39.922099 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602859922097, "job": 6776, "event": "table_file_deletion",
"file_number": 17651}
2019-04-07 04:07:39.922129 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1403]
[default] [JOB 6777] Compacting 1@1 + 9@2 files to L2, score 1.15
2019-04-07 04:07:39.922141 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1407]
[default] Compaction start summary: Base version 6776 Base level 1, inputs:
[17660(32MB)], [17625(66MB) 17626(66MB) 17627(66MB) 17628(66MB) 17629(66MB)
17630(65MB) 17631(65MB) 17632(66MB) 17633(14MB)]
2019-04-07 04:07:39.922156 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602859922146, "job": 6777, "event": "compaction_started",
"files_L1": [17660], "files_L2": [17625, 17626, 17627, 17628, 17629, 17630,
17631, 17632, 17633], "score": 1.1502, "input_data_size": 602419380}
2019-04-07 04:07:40.744829 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6777] Generated table #17661: 276977 keys, 69274076 bytes
2019-04-07 04:07:40.744852 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602860744839, "cf_name": "default", "job": 6777, "event":
"table_file_creation", "file_number": 17661, "file_size": 69274076,
"table_properties": {"data_size": 67111211, "index_size": 1318246,
"filter_size": 843632, "raw_key_size": 18534383, "raw_average_key_size": 66,
"raw_value_size": 60026009, "raw_average_value_size": 216, "num_data_blocks":
17264, "num_entries": 276977, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2019-04-07 04:07:41.511959 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6777] Generated table #17662: 140524 keys, 69244885 bytes
2019-04-07 04:07:41.511981 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602861511969, "cf_name": "default", "job": 6777, "event":
"table_file_creation", "file_number": 17662, "file_size": 69244885,
"table_properties": {"data_size": 67111835, "index_size": 1631726,
"filter_size": 500337, "raw_key_size": 12306449, "raw_average_key_size": 87,
"raw_value_size": 62685069, "raw_average_value_size": 446, "num_data_blocks":
17643, "num_entries": 140524, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2019-04-07 04:07:42.069833 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6777] Generated table #17663: 140480 keys, 69251237 bytes
2019-04-07 04:07:42.069869 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602862069856, "cf_name": "default", "job": 6777, "event":
"table_file_creation", "file_number": 17663, "file_size": 69251237,
"table_properties": {"data_size": 67109985, "index_size": 1640069,
"filter_size": 500196, "raw_key_size": 12302449, "raw_average_key_size": 87,
"raw_value_size": 62675074, "raw_average_value_size": 446, "num_data_blocks":
17640, "num_entries": 140480, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2019-04-07 04:07:42.642029 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6777] Generated table #17664: 139272 keys, 69253218 bytes
2019-04-07 04:07:42.642052 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602862642040, "cf_name": "default", "job": 6777, "event":
"table_file_creation", "file_number": 17664, "file_size": 69253218,
"table_properties": {"data_size": 67110463, "index_size": 1643899,
"filter_size": 497869, "raw_key_size": 12204956, "raw_average_key_size": 87,
"raw_value_size": 62802099, "raw_average_value_size": 450, "num_data_blocks":
17411, "num_entries": 139272, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2019-04-07 04:07:43.193906 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6777] Generated table #17665: 137243 keys, 69246759 bytes
2019-04-07 04:07:43.193929 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602863193917, "cf_name": "default", "job": 6777, "event":
"table_file_creation", "file_number": 17665, "file_size": 69246759,
"table_properties": {"data_size": 67109536, "index_size": 1642532,
"filter_size": 493704, "raw_key_size": 12037721, "raw_average_key_size": 87,
"raw_value_size": 62982021, "raw_average_value_size": 458, "num_data_blocks":
17097, "num_entries": 137243, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2019-04-07 04:07:43.761758 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6777] Generated table #17666: 135162 keys, 69051020 bytes
2019-04-07 04:07:43.761787 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602863761769, "cf_name": "default", "job": 6777, "event":
"table_file_creation", "file_number": 17666, "file_size": 69051020,
"table_properties": {"data_size": 67109890, "index_size": 1450482,
"filter_size": 489661, "raw_key_size": 12376157, "raw_average_key_size": 91,
"raw_value_size": 61429503, "raw_average_value_size": 454, "num_data_blocks":
16988, "num_entries": 135162, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2019-04-07 04:07:44.327604 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6777] Generated table #17667: 133378 keys, 69020961 bytes
2019-04-07 04:07:44.327626 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602864327612, "cf_name": "default", "job": 6777, "event":
"table_file_creation", "file_number": 17667, "file_size": 69020961,
"table_properties": {"data_size": 67110737, "index_size": 1425244,
"filter_size": 483993, "raw_key_size": 12534775, "raw_average_key_size": 93,
"raw_value_size": 61140547, "raw_average_value_size": 458, "num_data_blocks":
17387, "num_entries": 133378, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2019-04-07 04:07:45.044919 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6777] Generated table #17668: 396785 keys, 69611983 bytes
2019-04-07 04:07:45.044942 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865044930, "cf_name": "default", "job": 6777, "event":
"table_file_creation", "file_number": 17668, "file_size": 69611983,
"table_properties": {"data_size": 67109377, "index_size": 1359121,
"filter_size": 1142498, "raw_key_size": 16160193, "raw_average_key_size": 40,
"raw_value_size": 57883184, "raw_average_value_size": 145, "num_data_blocks":
16787, "num_entries": 396785, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2019-04-07 04:07:45.363895 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1116]
[default] [JOB 6777] Generated table #17669: 438661 keys, 14797153 bytes
2019-04-07 04:07:45.363918 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865363906, "cf_name": "default", "job": 6777, "event":
"table_file_creation", "file_number": 17669, "file_size": 14797153,
"table_properties": {"data_size": 13573795, "index_size": 95878, "filter_size":
1126494, "raw_key_size": 7895898, "raw_average_key_size": 18, "raw_value_size":
7018576, "raw_average_value_size": 16, "num_data_blocks": 3324, "num_entries":
438661, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys":
"0", "kMergeOperands": "1"}}
2019-04-07 04:07:45.363942 7fba230c1700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:1173]
[default] [JOB 6777] Compacted 1@1 + 9@2 files to L2 => 568751292 bytes
2019-04-07 04:07:45.364584 7fba230c1700 4 rocksdb: (Original Log Time
2019/04/07-04:07:45.364412)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/compaction_job.cc:621]
[default] compacted to: base level 1 max bytes base 268435456 files[0 0 9 0 0 0
0] max score 0.21, MB/sec: 110.7 rd, 104.5 wr, level 2, files in(1, 9) out(9)
MB in(32.2, 542.3) out(542.4), read-write-amplify(34.7) write-amplify(16.8) OK,
records in: 2906082, records dropped: 950676
2019-04-07 04:07:45.364591 7fba230c1700 4 rocksdb: (Original Log Time
2019/04/07-04:07:45.364429) EVENT_LOG_v1 {"time_micros": 1554602865364421,
"job": 6777, "event": "compaction_finished", "compaction_time_micros": 5441771,
"output_level": 2, "num_output_files": 9, "total_output_size": 568751292,
"num_input_records": 2889158, "num_output_records": 1938482,
"num_subcompactions": 1, "num_single_delete_mismatches": 0,
"num_single_delete_fallthrough": 0, "lsm_state": [0, 0, 9, 0, 0, 0, 0]}
2019-04-07 04:07:45.364621 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364618, "job": 6777, "event": "table_file_deletion",
"file_number": 17660}
2019-04-07 04:07:45.364634 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364632, "job": 6777, "event": "table_file_deletion",
"file_number": 17633}
2019-04-07 04:07:45.364641 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364640, "job": 6777, "event": "table_file_deletion",
"file_number": 17632}
2019-04-07 04:07:45.364648 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364646, "job": 6777, "event": "table_file_deletion",
"file_number": 17631}
2019-04-07 04:07:45.364655 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364653, "job": 6777, "event": "table_file_deletion",
"file_number": 17630}
2019-04-07 04:07:45.364662 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364661, "job": 6777, "event": "table_file_deletion",
"file_number": 17629}
2019-04-07 04:07:45.364668 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364666, "job": 6777, "event": "table_file_deletion",
"file_number": 17628}
2019-04-07 04:07:45.364673 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364672, "job": 6777, "event": "table_file_deletion",
"file_number": 17627}
2019-04-07 04:07:45.364682 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364681, "job": 6777, "event": "table_file_deletion",
"file_number": 17626}
2019-04-07 04:07:45.364690 7fba230c1700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554602865364688, "job": 6777, "event": "table_file_deletion",
"file_number": 17625}
2019-04-07 04:13:57.436121 7fba248c4700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_write.cc:684] reusing
log 17656 from recycle list
2019-04-07 04:13:57.436193 7fba248c4700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_write.cc:725]
[default] New memtable created with log file: #17670. Immutable memtables: 0.
2019-04-07 04:13:57.436823 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:13:57.436219)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_compaction_flush.cc:1158]
Calling FlushMemTableToOutputFile with column family [default], flush slots
available 1, compaction slots allowed 1, compaction slots scheduled 1
2019-04-07 04:13:57.436830 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/flush_job.cc:264] [default]
[JOB 6778] Flushing memtable with next log file: 17670
2019-04-07 04:13:57.436841 7fba0e097700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554603237436835, "job": 6778, "event": "flush_started",
"num_memtables": 1, "num_entries": 324345, "num_deletes": 71811,
"memory_usage": 260051432}
2019-04-07 04:13:57.436844 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/flush_job.cc:293] [default]
[JOB 6778] Level-0 flush table #17671: started
2019-04-07 04:13:57.576432 7fba0e097700 4 rocksdb: EVENT_LOG_v1
{"time_micros": 1554603237576418, "cf_name": "default", "job": 6778, "event":
"table_file_creation", "file_number": 17671, "file_size": 10994576,
"table_properties": {"data_size": 10476335, "index_size": 160495,
"filter_size": 356757, "raw_key_size": 7048685, "raw_average_key_size": 52,
"raw_value_size": 8119636, "raw_average_value_size": 60, "num_data_blocks":
2614, "num_entries": 133225, "filter_policy_name":
"rocksdb.BuiltinBloomFilter", "kDeletedKeys": "71818", "kMergeOperands":
"2631"}}
2019-04-07 04:13:57.576442 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/flush_job.cc:319] [default]
[JOB 6778] Level-0 flush table #17671: 10994576 bytes OK
2019-04-07 04:13:57.576892 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_files.cc:242] adding
log 17658 to recycle list
2019-04-07 04:13:57.576898 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:13:57.576448)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/memtable_list.cc:360]
[default] Level-0 commit table #17671 started
2019-04-07 04:13:57.576901 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:13:57.576861)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/memtable_list.cc:383]
[default] Level-0 commit table #17671: memtable #1 done
2019-04-07 04:13:57.576903 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:13:57.576870) EVENT_LOG_v1 {"time_micros": 1554603237576865,
"job": 6778, "event": "flush_finished", "lsm_state": [1, 0, 9, 0, 0, 0, 0],
"immutable_memtables": 0}
2019-04-07 04:13:57.576905 7fba0e097700 4 rocksdb: (Original Log Time
2019/04/07-04:13:57.576885)
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_compaction_flush.cc:132]
[default] Level summary: base level 1 max bytes base 268435456 files[1 0 9 0 0
0 0] max score 0.25
2019-04-07 04:13:57.576908 7fba0e097700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_files.cc:388] [JOB
6778] Try to delete WAL files size 253685940, prev total WAL file size
253731998, number of live WAL files 2.
2019-04-07 04:21:13.590940 7fba248c4700 4 rocksdb:
[/builddir/build/BUILD/ceph-12.2.8/src/rocksdb/db/db_impl_write.cc:684] reusing
log 17658 from recycle list
= = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =
And finally, the "spikes" I'm talking about looks like this,
https://imgur.com/rAbUycf and is gathered with the following query in grafana,
"""" max(
irate(node_disk_write_time_ms{device=~"dm-.*",instance=~"[[osd_servers]].*"}[30s])
/
irate(node_disk_writes_completed{device=~"dm-.*",instance=~"[[osd_servers]].*"}[30s])
) by(device) """"
Is this "normal" and thus something one not should worry about, or should one
try to tune some parameters (and if so which one's) to get rid of them ?
Non the less it's a bit "worrying" with these latency spikes.
Any insight on this would be valuable.
Ps. Sorry if this has been posted or asked before. I couldn't find any current
threads/issues that seemed spot on to me.
Best Regards,
Patrik Martinsson - Linux System Administrator
Sweden
_______________________________________________
ceph-users mailing list
[email protected]
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
