|
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 ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
