Bug #39318: w_await high when rockdb compacting - bluestore - Ceph

Actions

Copy link

#1

Updated by hoan nv about 5 years ago

Please update issue object to 'high w_await when rockdb compact'.
Thanks

Actions

Copy link

#2

Updated by Nathan Cutler about 5 years ago

Subject changed from [] to w_await high when rockdb compacting

Actions

Copy link

#3

Updated by hoan nv about 5 years ago

update.

my log in attach file.

rocksdb of osd compact after 30 minutes. i thinks it too fast.

when osd has this log .

2019-04-22 08:27:00.029 7fcdf7447700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1555896420030536, "job": 1891, "event": "table_file_deletion", "file_number": 74852}

w_await ( use iostat command) increase to 500.

Actions

Copy link

#4

Updated by hoan nv about 5 years ago

File log-compact-ceph log-compact-ceph added

Actions

Copy link

#5

Updated by Sage Weil about 5 years ago

Status changed from New to 4

This sounds like the SSD is just busy from compaction and/or client work. The w_await latency does sound a bit high but I don't think anything is broken. Mark, do you have any sense of what w_await values are typical during compaction?

Actions

Copy link

#6

Updated by Mark Nelson about 5 years ago

w_await is literally how long it's taking for the device to service requests. If the latency is increasing that means the device is being saturated. There's no standard for w_await times, every device will be different. FWIW I ran the log through my compaction event analyzer (https://github.com/ceph/cbt/blob/master/tools/ceph_rocksdb_log_parser.py):

$ ~/src/cbt/tools/ceph_rocksdb_log_parser.py -s SUMMARY log-compact-ceph
Compaction Statistics log-compact-ceph
Total OSD Log Duration (seconds) 3901.452
Number of Compaction Events 2
Avg Compaction Time (seconds) 16.789999
Total Compaction Time (seconds) 33.579998
Avg Output Size: (MB) 445.891469002
Total Output Size: (MB) 891.782938004
Total Input Records 17096836
Total Output Records 16772705
Avg Output Throughput (MB/s) 26.5569149041
Avg Input Records/second 509134.588671
Avg Output Records/second 499481.8232
Avg Output/Input Ratio 0.981039334397

That output MB/s rate is pretty low. I just checked my dev box with an old LSI Nytro warp SSD and see: 127MB/s and on our Incerta test nodes with Intel P3700 NVMe drives I see 175MB/s:

$ ~/src/cbt/tools/ceph_rocksdb_log_parser.py -s SUMMARY /tmp/cbt/ceph/log/osd.0.log
Compaction Statistics /tmp/cbt/ceph/log/osd.0.log
Total OSD Log Duration (seconds) 249014.234
Number of Compaction Events 903
Avg Compaction Time (seconds) 1.47857799889
Total Compaction Time (seconds) 1335.155933
Avg Output Size: (MB) 217.804265428
Total Output Size: (MB) 196677.251681
Total Input Records 1002905491
Total Output Records 722756157
Avg Output Throughput (MB/s) 175.172146374
Avg Input Records/second 913748.31391
Avg Output Records/second 623725.310976
Avg Output/Input Ratio 0.712566307625

One thing I noticed is that you seem to have bigger compaction events and smaller records (nearly as high output records/second with much lower throughput). Are you using the standard bluestore rocksdb settings?

Potentially there is good news: Adam is seeing lower write amplification during compaction when experimenting with trocksdb (https://github.com/ToshibaMemoryAmerica/trocksdb). There's no guarantee that we will be able to use it, but this may be a way in the future to reduce the amount of work rocksdb does during compaction (so instead of making the device faster, there will be less work for it to do overall).

Mark

Actions

Copy link Download all files

#7

Updated by hoan nv about 5 years ago

File Grafana - osd -latency.png Grafana - osd -latency.png added
File Grafana - osd-write-latency.png Grafana - osd-write-latency.png added

My config rocksdb.

bluestore_rocksdb_options = "compression=kSnappyCompression,max_write_buffer_number=16,min_write_buffer_number_to_merge=3,recycle_log_file_num=16,write_buffer_size=268435456,writable_file_max_buffer_size=0,compaction_readahead_size=5242880,compaction_threads=40,flusher_threads=20"

log rocksdb compacting

Uptime(secs): 32295.2 total, 985.0 interval
Cumulative writes: 4109K writes, 21M keys, 4109K commit groups, 1.0 writes per commit group, ingest: 42.37 GB, 1.34 MB/s
Cumulative WAL: 4109K writes, 1970K syncs, 2.09 writes per sync, written: 42.37 GB, 1.34 MB/s
Cumulative stall: 00:00:0.000 H:M:S, 0.0 percent
Interval writes: 225K writes, 1049K keys, 225K commit groups, 1.0 writes per commit group, ingest: 2951.66 MB, 3.00 MB/s
Interval WAL: 225K writes, 109K syncs, 2.05 writes per sync, written: 2.88 MB, 3.00 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   47.40 MB   1.0      0.0     0.0      0.0       0.8      0.8       0.0   1.0      0.0     36.2        22        60    0.371       0      0
  L1      3/0   151.12 MB   0.8      2.9     0.7      2.2       2.3      0.1       0.0   3.1     42.3     33.5        70        14    5.011     28M  1849K
  L2     19/0    1.10 GB   0.4      1.5     0.2      1.3       1.3     -0.0       0.0   6.3     48.2     41.4        32         3   10.597     12M  4490K
 Sum     26/0    1.30 GB   0.0      4.4     0.9      3.4       4.4      0.9       0.0   5.5     36.2     36.0       124        77    1.613     41M  6339K
 Int      0/0    0.00 KB   0.0      0.2     0.1      0.1       0.2      0.1       0.0   4.2     32.2     34.3         6         5    1.157   1231K    73K
Uptime(secs): 32295.2 total, 985.0 interval
Flush(GB): cumulative 0.787, interval 0.046
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: 4.37 GB write, 0.14 MB/s write, 4.39 GB read, 0.14 MB/s read, 124.2 seconds
Interval compaction: 0.19 GB write, 0.20 MB/s write, 0.18 GB read, 0.19 MB/s read, 5.8 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 pendin
g_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   47.40 MB   1.0      0.0     0.0      0.0       0.8      0.8       0.0   1.0      0.0     36.2        22        60    0.371       0      0
  L1      3/0   151.12 MB   0.8      2.9     0.7      2.2       2.3      0.1       0.0   3.1     42.3     33.5        70        14    5.011     28M  1849K
  L2     19/0    1.10 GB   0.4      1.5     0.2      1.3       1.3     -0.0       0.0   6.3     48.2     41.4        32         3   10.597     12M  4490K
 Sum     26/0    1.30 GB   0.0      4.4     0.9      3.4       4.4      0.9       0.0   5.5     36.2     36.0       124        77    1.613     41M  6339K
 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): 32295.2 total, 0.0 interval
Flush(GB): cumulative 0.787, 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: 4.37 GB write, 0.14 MB/s write, 4.39 GB read, 0.14 MB/s read, 124.2 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 pendin
g_compaction_bytes, 0 memtable_compaction, 0 memtable_slowdown, interval 0 total count

** File Read Latency Histogram By Level [default] **

2019-04-26 09:06:57.109 7f5903d02700  4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/h
uge/release/13.2.5/rpm/el7/BUILD/ceph-13.2.5/src/rocksdb/db/compaction_job.cc:1494] [default] [JOB 79] Compacting 4@0 + 3@1 files to L1, score 1.00
2019-04-26 09:06:57.109 7f5903d02700  4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/h
uge/release/13.2.5/rpm/el7/BUILD/ceph-13.2.5/src/rocksdb/db/compaction_job.cc:1498] [default] Compaction start summary: Base version 80 Base level 0, inputs: [73347(14MB) 73343(14MB
) 73339(9813KB) 73335(9752KB)], [73329(65MB) 73330(65MB) 73331(19MB)]

2019-04-26 09:06:57.109 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244417110042, "job": 79, "event": "compaction_started", "files_L0": [73347, 73343, 73339, 73335], " 
files_L1": [73329, 73330, 73331], "score": 1, "input_data_size": 208164366}
2019-04-26 09:06:59.540 7f5903d02700  4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/h
uge/release/13.2.5/rpm/el7/BUILD/ceph-13.2.5/src/rocksdb/db/compaction_job.cc:1166] [default] [JOB 79] Generated table #73348: 495873 keys, 68983600 bytes
2019-04-26 09:06:59.541 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244419542196, "cf_name": "default", "job": 79, "event": "table_file_creation", "file_number": 73348, "file_size": 68983600, "table_properties": {"data_size": 67112684, "index_size": 1508679, "filter_size": 1396626, "raw_key_size": 44914411, "raw_average_key_size": 90, "raw_value_size": 107965452, "raw_average_value_size": 217, "num_data_blocks": 17521, "num_entries": 495873, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "278154", "kMergeOperands": "0"}}
2019-04-26 09:07:01.451 7f5903d02700  4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.5/rpm/el7/BUILD/ceph-13.2.5/src/rocksdb/db/compaction_job.cc:1166] [default] [JOB 79] Generated table #73349: 366583 keys, 68636815 bytes
2019-04-26 09:07:01.451 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244421452332, "cf_name": "default", "job": 79, "event": "table_file_creation", "file_number": 73349, "file_size": 68636815, "table_properties": {"data_size": 67110604, "index_size": 1350785, "filter_size": 1075792, "raw_key_size": 32156342, "raw_average_key_size": 87, "raw_value_size": 113533715, "raw_average_value_size": 309, "num_data_blocks": 15659, "num_entries": 366583, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "221431", "kMergeOperands": "0"}}
2019-04-26 09:07:02.578 7f5903d02700  4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.5/rpm/el7/BUILD/ceph-13.2.5/src/rocksdb/db/compaction_job.cc:1166] [default] [JOB 79] Generated table #73350: 534451 keys, 31215515 bytes
2019-04-26 09:07:02.578 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244422579595, "cf_name": "default", "job": 79, "event": "table_file_creation", "file_number": 73350, "file_size": 31215515, "table_properties": {"data_size": 29452481, "index_size": 1012897, "filter_size": 1406552, "raw_key_size": 27939801, "raw_average_key_size": 52, "raw_value_size": 70406148, "raw_average_value_size": 131, "num_data_blocks": 14873, "num_entries": 534451, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "271353", "kMergeOperands": "10782"}}
2019-04-26 09:07:02.578 7f5903d02700  4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.5/rpm/el7/BUILD/ceph-13.2.5/src/rocksdb/db/compaction_job.cc:1244] [default] [JOB 79] Compacted 4@0 + 3@1 files to L1 => 168835930 bytes
2019-04-26 09:07:02.608 7f5903d02700  4 rocksdb: (Original Log Time 2019/04/26-09:07:02.609780) [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/13.2.5/rpm/el7/BUILD/ceph-13.2.5/src/rocksdb/db/compaction_job.cc:642] [default] compacted to: base level 1 max bytes base 268435456 files[0 3 19 0 0 0 0] max score 0.81, MB/sec: 38.1 rd, 30.9 wr, level 1, files in(4, 3) out(3) MB in(47.4, 151.1) out(161.0), read-write-amplify(7.6) write-amplify(3.4) OK, records in: 1473379, records dropped: 75769
2019-04-26 09:07:02.608 7f5903d02700  4 rocksdb: (Original Log Time 2019/04/26-09:07:02.609803) EVENT_LOG_v1 {"time_micros": 1556244422609794, "job": 79, "event": "compaction_finished", "compaction_time_micros": 5469731, "output_level": 1, "num_output_files": 3, "total_output_size": 168835930, "num_input_records": 1472676, "num_output_records": 1396907, "num_subcompactions": 1, "output_compression": "Snappy", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 3, 19, 0, 0, 0, 0]}
2019-04-26 09:07:02.608 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244422609968, "job": 79, "event": "table_file_deletion", "file_number": 73347}
2019-04-26 09:07:02.608 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244422610039, "job": 79, "event": "table_file_deletion", "file_number": 73343}
2019-04-26 09:07:02.608 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244422610109, "job": 79, "event": "table_file_deletion", "file_number": 73339}
2019-04-26 09:07:02.608 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244422610172, "job": 79, "event": "table_file_deletion", "file_number": 73335}
2019-04-26 09:07:02.609 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244422610227, "job": 79, "event": "table_file_deletion", "file_number": 73331}
2019-04-26 09:07:02.609 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244422610283, "job": 79, "event": "table_file_deletion", "file_number": 73330}
2019-04-26 09:07:02.609 7f5903d02700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1556244422610340, "job": 79, "event": "table_file_deletion", "file_number": 73329}

2 image show osd latency and disk w_await in attach file

if bluestore_rocksdb_options has default value, osd latency and disk write latency increase.

thanks.

Actions

Copy link

#8

Updated by hoan nv almost 5 years ago

@Mark

Do you need more information?

Actions

Copy link

#9

Updated by hoan nv almost 5 years ago

File Grafana - write latency after tuning rocksdb.png Grafana - write latency after tuning rocksdb.png added

use rocksdb tuning options in tuning guide : https://ceph.com/community/bluestore-default-vs-tuned-performance-comparison/

bluestore_rocksdb_options = compression=kNoCompression,max_write_buffer_number=32,min_write_buffer_number_to_merge=2,recycle_log_file_num=32,compaction_style=kCompactionStyleLevel,write_buffer_size=67108864,target_file_size_base=67108864,max_background_compactions=31,level0_file_num_compaction_trigger=8,level0_slowdown_writes_trigger=32,level0_stop_writes_trigger=64,max_bytes_for_level_base=536870912,compaction_threads=32,max_bytes_for_level_multiplier=8,flusher_threads=8,compaction_readahead_size=2MB

latency reduce to < 20 ms

image in attach file.

Actions

Copy link

#10

Updated by hoan nv almost 5 years ago

i found an issue same my issue

https://tracker.ceph.com/issues/23819

Actions

Copy link

#11

Updated by Neha Ojha over 4 years ago

Related to Bug #23819: how to make compactions smooth added

Actions

Copy link

#12

Updated by Patrick Donnelly over 4 years ago

Status changed from 4 to New

Actions

Copy link

#13

Updated by Francois Scheurer about 2 years ago

hoan nv wrote:

use rocksdb tuning options in tuning guide : https://ceph.com/community/bluestore-default-vs-tuned-performance-comparison/

[...]

latency reduce to < 20 ms

image in attach file.

Huge Thanks to Hoan for these tuning options !!!
We had also high latencies with EC8+2 pools (on nvme with nautilus 14.2.12).
These options fixed them. (at least for the time being, we did the change only 12 hours ago)

Actions

Copy link

#14

Updated by Igor Fedotov 6 months ago

Status changed from New to Closed

Recently we had a bunch of Rocksdb tunings which hopefully fix the compaction behavior:

-https://github.com/ceph/ceph/pull/47221
-https://github.com/ceph/ceph/pull/51821
-https://github.com/ceph/ceph/pull/53343

Hence closing.

log-compact-ceph (209 KB) log-compact-ceph		hoan nv, 04/22/2019 02:43 AM
Grafana - osd-write-latency.png (26.7 KB) Grafana - osd-write-latency.png	disk write latency	hoan nv, 04/26/2019 02:33 AM
Grafana - osd -latency.png (56.5 KB) Grafana - osd -latency.png	osd latency	hoan nv, 04/26/2019 02:33 AM
Grafana - write latency after tuning rocksdb.png (30.4 KB) Grafana - write latency after tuning rocksdb.png	write latency after tuning rocksdb	hoan nv, 05/08/2019 03:29 AM

Project

General

Profile

Ceph » bluestore

Custom queries

Bug #39318

w_await high when rockdb compacting

Updated by hoan nv about 5 years ago

Updated by Nathan Cutler about 5 years ago

Updated by hoan nv about 5 years ago

Updated by hoan nv about 5 years ago

Updated by Sage Weil about 5 years ago

Updated by Mark Nelson about 5 years ago

Updated by hoan nv about 5 years ago

Updated by hoan nv almost 5 years ago

Updated by hoan nv almost 5 years ago

Updated by hoan nv almost 5 years ago

Updated by Neha Ojha over 4 years ago

Updated by Patrick Donnelly over 4 years ago

Updated by Francois Scheurer about 2 years ago

Updated by Igor Fedotov 6 months ago