Ceph » bluestore

Here is my analysis from what I've seen in your logs so far:
1) After initial issue(s) that trigger OSDs to restart (haven't investigated what was it) they are facing a bunch of issues with allocating additional space for bluefs. The latter attempts to get more space to recover after the initial failure - most probably to replay WAL and flush DB data to DB/main volumes. The key thing is that this allocation differs from the regular ones and tend to quite large. Which probably reals most of the subsequent issues. Ones that I could see in your logs (including ones got from the previous ceph-users posts).

1) http://tracker.ceph.com/issues/40080 - bitmap allocator returns duplicate entries (fixed in master branch and approved and awaiting for qa for nautilus). Not 100% sure since the provided logs lacks some key information but highly likely this happened for the first log you shared.
2) http://tracker.ceph.com/issues/40703 - stupid allocator might return extents of 0 bytes length. Fix is approved and pending QA. This was observed in log shared here : https://pastebin.com/yuJKcPvX. Reproduced in the lab as well.
3)From the log attached to this ticket it looks like lack of space (partially caused by high fragmentation) is observed for this specific OSD:
-31> 2019-07-11 18:47:54.676 7f9fd6424d80 1 bluefs _allocate failed to allocate 0xcd00000 on bdev 1, free 0x2300000; fallback to bdev 2
^^^ Failing to allocate ~200 MB from DB volume which has just ~35MB free.

-30> 2019-07-11 18:47:54.676 7f9fd6424d80  1 bluefs _allocate unable to allocate 0xcd00000 on bdev 2, free 0xffffffffffffffff; fallback to slow device expander 
^^^ Failing to allocate ~214 MB from already allocated bluefs part of the main device, Failing to do that, reported free space value 0xffffffffffffffff looks suspicious but nevertheless going to take more space from main device for bluefs.

-29> 2019-07-11 18:47:54.676 7f9fd6424d80 10 bluestore(/var/lib/ceph/osd/ceph-123) _get_bluefs_size_delta bluefs 35 MiB free (8.11483e-05) bluestore 741 MiB free (0.00162123), bluefs_ratio 0.0450768
   -28> 2019-07-11 18:47:54.676 7f9fd6424d80 10 bluestore(/var/lib/ceph/osd/ceph-123) allocate_bluefs_freespace gifting 214958080 (205 MiB)
^^^ performing the allocation from the main device....
   -27> 2019-07-11 18:47:54.676 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 allocate 0xcd00000/100000,0,0
   -26> 2019-07-11 18:47:54.677 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 allocate 0x59e00000~100000/100000,0,0
   -25> 2019-07-11 18:47:54.677 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 allocate 0x592b00000~200000/100000,0,0
   -24> 2019-07-11 18:47:54.677 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 allocate 0x5531000000~100000/100000,0,0
   -23> 2019-07-11 18:47:54.677 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 allocate 0x555fa00000~100000/100000,0,0
   -22> 2019-07-11 18:47:54.677 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 allocate 0x5ec2300000~300000/100000,0,0
   -21> 2019-07-11 18:47:54.677 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 allocate 0x5eda900000~300000/100000,0,0
   -20> 2019-07-11 18:47:54.677 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 allocate 0x6c11700000~300000/100000,0,0
   -19> 2019-07-11 18:47:54.677 7f9fd6424d80 -1 bluestore(/var/lib/ceph/osd/ceph-123) allocate_bluefs_freespace failed to allocate on 0xcd00000 min_size 0xcd00000 > allocated total 0xe00000 bluefs_alloc_size 0x100000 allocated 0xe00000 available 0x 2d774000
^^ failed to do that, only 14Mb is available in contiguous 1MB chunks. Totally ~760MB free is available at main device. Which is terribly low in fact!!!

-18> 2019-07-11 18:47:54.681 7f9fd6424d80  0 fbmap_alloc 0x561e2045dd00 dump bin 0(< 32 KiB) : 4095 extents
   -17> 2019-07-11 18:47:54.681 7f9fd6424d80  0 fbmap_alloc 0x561e2045dd00 dump bin 1(< 64 KiB) : 1559 extents
   -16> 2019-07-11 18:47:54.681 7f9fd6424d80  0 fbmap_alloc 0x561e2045dd00 dump bin 2(< 128 KiB) : 1025 extents
   -15> 2019-07-11 18:47:54.681 7f9fd6424d80  0 fbmap_alloc 0x561e2045dd00 dump bin 3(< 256 KiB) : 386 extents
   -14> 2019-07-11 18:47:54.681 7f9fd6424d80  0 fbmap_alloc 0x561e2045dd00 dump bin 4(< 512 KiB) : 341 extents
   -13> 2019-07-11 18:47:54.681 7f9fd6424d80  0 fbmap_alloc 0x561e2045dd00 dump bin 5(< 1 MiB) : 364 extents
   -12> 2019-07-11 18:47:54.681 7f9fd6424d80  0 fbmap_alloc 0x561e2045dd00 dump bin 6(< 2 MiB) : 68 extents
   -11> 2019-07-11 18:47:54.681 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 release 0x59e00000~100000
   -10> 2019-07-11 18:47:54.681 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 release 0x592b00000~200000
    -9> 2019-07-11 18:47:54.681 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 release 0x5531000000~100000
    -8> 2019-07-11 18:47:54.681 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 release 0x555fa00000~100000
    -7> 2019-07-11 18:47:54.681 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 release 0x5ec2300000~300000
    -6> 2019-07-11 18:47:54.681 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 release 0x5eda900000~300000
    -5> 2019-07-11 18:47:54.681 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 release 0x6c11700000~300000
    -4> 2019-07-11 18:47:54.681 7f9fd6424d80 10 fbmap_alloc 0x561e2045dd00 release done
    -3> 2019-07-11 18:47:54.681 7f9fd6424d80 -1 bluefs _allocate failed to expand slow device to fit +0xcd00000
    -2> 2019-07-11 18:47:54.681 7f9fd6424d80 -1 bluefs _flush_range allocated: 0x0 offset: 0x0 length: 0xccf60b1
 -1> 2019-07-11 18:47:54.688 7f9fd6424d80 -1 /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/14.2.1/rpm/el7/BUILD/ceph-14.2.1/src/os/bluestore/BlueFS.cc: In function 'int BlueFS::_flush_range(BlueFS::FileWriter*, uint64_t, uint64_t)' thread 7f9fd6424d80 time 2019-07-11 18:47:54.682321
/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/14.2.1/rpm/el7/BUILD/ceph-14.2.1/src/os/bluestore/BlueFS.cc: 2044: abort()
^^^ aborting due to the lack of free space

So my general considerations/notes:
1) do OSD troubleshooting and repairing one by one - they have different issues. Do the fix for a single specific node and wait until it has started successfully. Proceeding cluster malfunction after applying some fix to all doesn't mean the fix doesn't help - you might simply get another issue.

2) revise free space at your OSDs - the existing report (just for a single OSD so far) shows very little space at both DB and main device.
3) I suggest to be careful with any massive data migrations (or preferably avoid them at all) unless you know exactly what's happening and why this will help..

Thanks for looking into Igor. That was one of the many failed SSD volumes, chosen at random. Here is some info from the first one to die (Didn't have debugging on when it died)

2019-07-11 08:13:00.966 7fc7a9b06700 0 osd.196 pg_epoch: 1352621 pg[60.32( v 1352617'911187 (1333356'908185,1352617'911187] lb 60:4db19752:::.meta%3abucket.instance%3adb_visibility_and_automation%2f2019-7-5-prod-log_file_type_oracle_sfcon_sql%3a8346a3be-abaa-4aa6-8d8a-f54818d16aef.146035057.1%3a_2oTtyanhCocW2sZKQjEgEme%3a27678:head (bitwise) local-lis/les=1352490/1352491 n=235514 ec=2213/2213 lis/c 1352490/1351508 les/c/f 1352491/1351509/0 1352489/1352490/1352490) [136,163,196]/[59,129,138] r=-1 lpr=1352490 pi=[1351508,1352490)/1 luod=0'0 lua=1352394'911185 crt=1352617'911187 active mbc={}] do_backfill primary 89225304 local 89225308
2019-07-11 08:13:00.971 7fc7bc32b700 1 bluefs _allocate failed to allocate 0x4300000 on bdev 1, free 0xc00000; fallback to bdev 2
2019-07-11 08:13:00.971 7fc7bc32b700 1 bluefs _allocate unable to allocate 0x4300000 on bdev 2, free 0xffffffffffffffff; fallback to slow device expander
2019-07-11 08:13:00.971 7fc7bc32b700 -1 bluestore(/var/lib/ceph/osd/ceph-196) allocate_bluefs_freespace failed to allocate on 0x4300000 min_size 0x4300000 > allocated total 0x1900000 bluefs_alloc_size 0x100000 allocated 0x1900000 available 0x 28c8000
2019-07-11 08:13:00.971 7fc7aab08700 0 osd.196 pg_epoch: 1352621 pg[60.8( v 1352621'819543 (1333060'816540,1352621'819543] lb 60:12631b8d:::.meta%3abucket.instance%3adb_visibility_and_automation%2f2019-5-12-prod-log_file_type_oracle_hourly_awr_text%3a8346a3be-abaa-4aa6-8d8a-f54818d16aef.126164230.1411%3a_gVWxpZjgXL1TJse8MuJNehU%3a7618:head (bitwise) local-lis/les=1352490/1352491 n=332210 ec=2213/2213 lis/c 1352490/1351448 les/c/f 1352491/1352064/0 1352523/1352523/1352490) [168,196,257]/[85,108,161] r=-1 lpr=1352523 pi=[1351448,1352523)/1 luod=0'0 lua=1352502'819541 crt=1352621'819543 active+remapped mbc={}] do_backfill primary 109664820 local 109665205
2019-07-11 08:13:00.979 7fc7bc32b700 0 fbmap_alloc 0x5555fd7fd300 dump bin 0(< 32 KiB) : 745 extents
2019-07-11 08:13:00.993 7fc7bc32b700 0 fbmap_alloc 0x5555fd7fd300 dump bin 1(< 64 KiB) : 188 extents
2019-07-11 08:13:00.993 7fc7bc32b700 0 fbmap_alloc 0x5555fd7fd300 dump bin 2(< 128 KiB) : 58 extents
2019-07-11 08:13:00.993 7fc7bc32b700 0 fbmap_alloc 0x5555fd7fd300 dump bin 3(< 256 KiB) : 17 extents
2019-07-11 08:13:00.993 7fc7bc32b700 0 fbmap_alloc 0x5555fd7fd300 dump bin 4(< 512 KiB) : 21 extents
2019-07-11 08:13:00.993 7fc7bc32b700 0 fbmap_alloc 0x5555fd7fd300 dump bin 5(< 1 MiB) : 6 extents
2019-07-11 08:13:00.993 7fc7bc32b700 0 fbmap_alloc 0x5555fd7fd300 dump bin 6(< 2 MiB) : 2 extents
2019-07-11 08:13:00.993 7fc7bc32b700 -1 bluefs _allocate failed to expand slow device to fit +0x4300000
2019-07-11 08:13:00.993 7fc7bc32b700 -1 bluefs _flush_range allocated: 0x0 offset: 0x0 length: 0x427347b
2019-07-11 08:13:01.121 7fc7a7301700 0 osd.196 pg_epoch: 1352621 pg[60.3f( v 1352609'842419 (1333048'839418,1352609'842419] lb 60:fe2b5ac9:::.meta%3abucket.instance%3adb_visibility_and_automation%2f2019-5-5-prod-log_file_type_oracle_sfcon_total%3a8346a3be-abaa-4aa6-8d8a-f54818d16aef.126164230.507%3a_EQ3kaoVN0q0czsMY73gVrpI%3a19950:head (bitwise) local-lis/les=1352490/1352491 n=301177 ec=2213/2213 lis/c 1352490/1351462 les/c/f 1352491/1351463/0 1352489/1352490/1352490) [123,196,151]/[8,26,251] r=-1 lpr=1352490 pi=[1351462,1352490)/1 luod=0'0 lua=1352392'842418 crt=1352609'842419 active mbc={}] do_backfill primary 114101245 local 114101239
2019-07-11 08:13:01.151 7fc7bc32b700 -1 /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/14.2.1/rpm/el7/BUILD/ceph-14.2.1/src/os/bluestore/BlueFS.cc: In function 'int BlueFS::_flush_range(BlueFS::FileWriter*, uint64_t, uint64_t)' thread 7fc7bc32b700 time 2019-07-11 08:13:01.001811
/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/14.2.1/rpm/el7/BUILD/ceph-14.2.1/src/os/bluestore/BlueFS.cc: 2044: abort()

ceph version 14.2.1 (d555a9489eb35f84f2e1ef49b77e19da9d113972) nautilus (stable)
 1: (ceph::__ceph_abort(char const*, int, char const*, std::string const&)+0xd8) [0x5555f1d01cd0]
 2: (BlueFS::_flush_range(BlueFS::FileWriter*, unsigned long, unsigned long)+0x1daf) [0x5555f23b99af]
 3: (BlueFS::_flush(BlueFS::FileWriter*, bool)+0x10b) [0x5555f23b9b4b]
 4: (BlueRocksWritableFile::Flush()+0x3d) [0x5555f23d784d]
 5: (rocksdb::WritableFileWriter::Flush()+0x19e) [0x5555f2a05d0e]
 6: (rocksdb::WritableFileWriter::Sync(bool)+0x2e) [0x5555f2a05fee]
 7: (rocksdb::CompactionJob::FinishCompactionOutputFile(rocksdb::Status const&, rocksdb::CompactionJob::SubcompactionState*, rocksdb::RangeDelAggregator*, CompactionIterationStats*, rocksdb::Slice const*)+0xbaa) [0x5555f2a5373a]
 8: (rocksdb::CompactionJob::ProcessKeyValueCompaction(rocksdb::CompactionJob::SubcompactionState*)+0x7d0) [0x5555f2a57150]
 9: (rocksdb::CompactionJob::Run()+0x298) [0x5555f2a58618]
 10: (rocksdb::DBImpl::BackgroundCompaction(bool*, rocksdb::JobContext*, rocksdb::LogBuffer*, rocksdb::DBImpl::PrepickedCompaction*)+0xcb7) [0x5555f2897b67]
 11: (rocksdb::DBImpl::BackgroundCallCompaction(rocksdb::DBImpl::PrepickedCompaction*, rocksdb::Env::Priority)+0xd0) [0x5555f28993c0]
 12: (rocksdb::DBImpl::BGWorkCompaction(void*)+0x3a) [0x5555f289990a]
 13: (rocksdb::ThreadPoolImpl::Impl::BGThread(unsigned long)+0x264) [0x5555f2aa59c4]
 14: (rocksdb::ThreadPoolImpl::Impl::BGThreadWrapper(void*)+0x4f) [0x5555f2aa5b4f]
 15: (()+0x129dfff) [0x5555f2b32fff]
 16: (()+0x7dd5) [0x7fc7c941add5]
 17: (clone()+0x6d) [0x7fc7c82e0ead]

2019-07-11 08:13:01.253 7fc7bc32b700 -1 ** Caught signal (Aborted) *
in thread 7fc7bc32b700 thread_name:rocksdb:low0

ceph version 14.2.1 (d555a9489eb35f84f2e1ef49b77e19da9d113972) nautilus (stable)
 1: (()+0xf5d0) [0x7fc7c94225d0]
 2: (gsignal()+0x37) [0x7fc7c8219207]
 3: (abort()+0x148) [0x7fc7c821a8f8]
 4: (ceph::__ceph_abort(char const*, int, char const*, std::string const&)+0x19c) [0x5555f1d01d94]
 5: (BlueFS::_flush_range(BlueFS::FileWriter*, unsigned long, unsigned long)+0x1daf) [0x5555f23b99af]
 6: (BlueFS::_flush(BlueFS::FileWriter*, bool)+0x10b) [0x5555f23b9b4b]
 7: (BlueRocksWritableFile::Flush()+0x3d) [0x5555f23d784d]
 8: (rocksdb::WritableFileWriter::Flush()+0x19e) [0x5555f2a05d0e]
 9: (rocksdb::WritableFileWriter::Sync(bool)+0x2e) [0x5555f2a05fee]
 10: (rocksdb::CompactionJob::FinishCompactionOutputFile(rocksdb::Status const&, rocksdb::CompactionJob::SubcompactionState*, rocksdb::RangeDelAggregator*, CompactionIterationStats*, rocksdb::Slice const*)+0xbaa) [0x5555f2a5373a]
 11: (rocksdb::CompactionJob::ProcessKeyValueCompaction(rocksdb::CompactionJob::SubcompactionState*)+0x7d0) [0x5555f2a57150]
 12: (rocksdb::CompactionJob::Run()+0x298) [0x5555f2a58618]
 13: (rocksdb::DBImpl::BackgroundCompaction(bool*, rocksdb::JobContext*, rocksdb::LogBuffer*, rocksdb::DBImpl::PrepickedCompaction*)+0xcb7) [0x5555f2897b67]
 14: (rocksdb::DBImpl::BackgroundCallCompaction(rocksdb::DBImpl::PrepickedCompaction*, rocksdb::Env::Priority)+0xd0) [0x5555f28993c0]
 15: (rocksdb::DBImpl::BGWorkCompaction(void*)+0x3a) [0x5555f289990a]
 16: (rocksdb::ThreadPoolImpl::Impl::BGThread(unsigned long)+0x264) [0x5555f2aa59c4]
 17: (rocksdb::ThreadPoolImpl::Impl::BGThreadWrapper(void*)+0x4f) [0x5555f2aa5b4f]
 18: (()+0x129dfff) [0x5555f2b32fff]
 19: (()+0x7dd5) [0x7fc7c941add5]
 20: (clone()+0x6d) [0x7fc7c82e0ead]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

This one doesn't have enough space as well, 0xc00000 bytes as ssd, 0x28c8000 bytes at main device. See:

2019-07-11 08:13:00.971 7fc7bc32b700 1 bluefs _allocate failed to allocate 0x4300000 on bdev 1, free 0xc00000; fallback to bdev 2
2019-07-11 08:13:00.971 7fc7bc32b700 1 bluefs _allocate unable to allocate 0x4300000 on bdev 2, free 0xffffffffffffffff; fallback to slow device expander
2019-07-11 08:13:00.971 7fc7bc32b700 -1 bluestore(/var/lib/ceph/osd/ceph-196) allocate_bluefs_freespace failed to allocate on 0x4300000 min_size 0x4300000 > allocated total 0x1900000 bluefs_alloc_size 0x100000 allocated 0x1900000 available 0x 28c8000

What's behind you DB volumes - LVM or plain partition/device?

Let's keep osd.44 aside for now. For 35 & 110 please answer/do the following.
1) Check corresponding disk activity for these specific osds. Are there any (more or less massive) disk read/writes observed for them after startup?
2) set debug bluefs to 20 (and debug osd back to default) - is osd log growing fast after that. In other words is there any massive BlueFS I/O present all the time?
3) If so - please do manual compaction for one of the osd using ceph-kvstore-tool (this might take a while). Then check for the presence of suicide timeout in the log again and/or check 1) & 2) above.

Do not set debug bluefs back to 5/5 when done.

Brett Chancellor wrote:

1. Info below
2. Attached last 50k lines of logs with debug_bluefs set to 20/20
3. Can you share the syntax for ceph-kvstore-tool? Is it something like ceph-kvstore-tool bluestore-kv /var/lib/ceph/osd/ceph-34 compact ?

yes, the syntax is like that

ceph-kvstore-tool bluestore-kv <path-to-osd> compact

Just to keep everybody aware - for these two osds the issue reminds me http://tracker.ceph.com/issues/36482

Wondering if you can have some custom build from sources to double check that?

Here is a summary of what we've discovered during this issue troubleshooting.
1) OSDs were dying due to suicide timeout, Mass heart beat timeouts were observed before
2) manual rocks db compaction helped for a while (several hours) and the issue reappeared again
3) Most of times one could see BlueStore collection_list function (called from PG::PG::do_delete_work) in backtraces printed after suicide.
4) Pool removal task running in background was found - it had been initiated several (3?) days before the troubleshooting session. Corresponding pool had ~32M objects. initially. Presumably this was <zone>.rgw.meta pool mentioned above.
5) Doing PG listing for the pool being removed using ceph-objectstore-tool was taking 20+ minutes and returned around 400K objects. Doing the same for other large pool took ~20 seconds (compare to minutes!) while returned just twice as less entries.
6) BlueFS allocated size on inspected OSDs was around 500GB which just 150GB of it residing at SSD drives. I.e. huge spillover took place.
7) Finally the hypothesis about very slow collection listing which blocks OSDs for a while has appeared. Such listings (max 30 entries per shot) are massively issued during pool removal. Due to lack of proper tooling we were unable to measure the duration for this short listings but most probably they were still very high which triggered heartbeat timeouts and finally caused suicides.
8) The suggested workaround is to stop background removal by tricking with RocksDB - remove root PG (aka collection) entries related to the bad pool from RocksDB using ceph-kvstore-tool, e.g. ceph-kvstore-tool bluestore-kv dev/osd0 rm C 5.35_head
9) Which finally prevented the issue from reappearance.
10) Hence my understanding of the issue (I'm not covering what was the initial trigger here) is as follows:
Massive record removal from huge DB residing mainly on rotational disk might cause very slow entry enumeration. Presumably this applies to enumerations that are related to already removed records. In our case both removed records and new enumerations were for the same collection. To some degree this reminds the issue we observed for slow omap listing here:
https://github.com/ceph/ceph/pull/27627
http://tracker.ceph.com/issues/36482
Where holes in DB made by massive removal caused slow omap listing tail seek.

And since collection_list is a synchronous call corresponding OSD threads stuck for a quite while.

BlueFS read prefetch and/or keeping DB at fast storage might reduce the negative impact but IMO the proper solution would be making collection_list call asynchronous.

I have same issue with you. Did you solve this issue? Could you update infor about this one?

Please see my previous comment, on-site issue has been worked around the way shared there.

But please be cautious when saying that your issue is exactly the same - one can get OSD crashes due to suicide timeouts under absolutely different scenarios....