Ceph » bluestore

Another attempt on a different host, now we upgrade just one 1T device...
I've set ceph config set osd bluestore_fsck_quick_fix_threads 1 since a race between the two ShallowFSCK threads seems likely.

But the upgrade seems to be failing again, the OSD doesn't report any more zombie spanning blobs, but consumes 100% cpu, in the main thread. ShallowFSCK thread has 0%. The log is silent, it doesn't react to daemon commands.

Attaching GDB:

#0  0x00007fed1ce91620 in tcmalloc::PageHeap::AllocLarge(unsigned long) () from target:/usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#1  0x00007fed1ce91e4f in tcmalloc::PageHeap::New(unsigned long) () from target:/usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#2  0x00007fed1ce907bf in tcmalloc::CentralFreeList::Populate() () from target:/usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#3  0x00007fed1ce909c8 in tcmalloc::CentralFreeList::FetchFromOneSpansSafe(int, void**, void**) () from target:/usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#4  0x00007fed1ce90abf in tcmalloc::CentralFreeList::RemoveRange(void**, void**, int) () from target:/usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#5  0x00007fed1ce93a5a in tcmalloc::ThreadCache::FetchFromCentralCache(unsigned long, unsigned long) () from target:/usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#6  0x00007fed1cea495b in tc_newarray () from target:/usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#7  0x0000561a1c78adcb in mempool::pool_allocator<(mempool::pool_index_t)8, BlueStore::Blob>::allocate (this=0x561a1d986e40 <mempool::bluestore_Blob::alloc_bluestore_blob>, n=1, p=0x0) at ./src/include/mempool.h:333
#8  BlueStore::Blob::operator new (size=<optimized out>) at ./src/os/bluestore/BlueStore.cc:72
#9  0x0000561a1c7ab8ba in BlueStore::ExtentMap::decode_some (this=this@entry=0x561a5dd2f550, bl=...) at ./src/os/bluestore/BlueStore.cc:3138
#10 0x0000561a1c7acd0c in BlueStore::Onode::decode (c=..., oid=..., key=..., v=...) at ./src/os/bluestore/BlueStore.cc:3620
#11 0x0000561a1c807c2b in BlueStore::fsck_check_objects_shallow (this=this@entry=0x561a27544000, depth=BlueStore::FSCK_SHALLOW, pool_id=<optimized out>, c=..., oid=..., key=..., value=..., expecting_shards=0x7fff49b7d9e0, referenced=0x7fff49b7d880, ctx=...)
    at ./src/os/bluestore/BlueStore.cc:7683
#12 0x0000561a1c80bb80 in BlueStore::_fsck_check_objects (this=this@entry=0x561a27544000, depth=depth@entry=BlueStore::FSCK_SHALLOW, ctx=...) at ./src/os/bluestore/BlueStore.cc:8339
#13 0x0000561a1c80fd4a in BlueStore::_fsck_on_open (this=this@entry=0x561a27544000, depth=depth@entry=BlueStore::FSCK_SHALLOW, repair=repair@entry=true) at ./src/os/bluestore/BlueStore.cc:8711
#14 0x0000561a1c82b9cd in BlueStore::_mount (this=0x561a27544000, kv_only=<optimized out>, open_db=<optimized out>) at ./src/os/bluestore/BlueStore.cc:7359
#15 0x0000561a1c33a381 in OSD::init (this=0x561a274ec000) at ./src/osd/OSD.cc:3291
#16 0x0000561a1c2a52cc in main (argc=<optimized out>, argv=<optimized out>) at ./src/ceph_osd.cc:711

perf top says:

  Children      Self  Shared Object         Symbol                                                                                                                                                                                                                                          
-   99.92%    98.21%  libtcmalloc.so.4.3.0  [.] tcmalloc::PageHeap::AllocLarge                                                                                                                                                                                                             ◆
   - 98.21% 0x19f                                                                                                                                                                                                                                                                          ▒
        tcmalloc::PageHeap::AllocLarge                                                                                                                                                                                                                                                     ▒
-   10.96%     0.00%  [unknown]             [.] 0x000000000000019f                                                                                                                                                                                                                         ▒
     0x19f                                                                                                                                                                                                                                                                                 ▒
     tcmalloc::PageHeap::AllocLarge                                                                                                                                                                                                                                                        ▒
-    0.85%     0.00%  [kernel]              [k] irq_exit                                                                                                                                                                                                                                   ▒
-    0.84%     0.01%  [kernel]              [k] __softirqentry_text_start                 

I've restarted the OSD, and it ran through the analysis this time, but corrupted again when committing.

[many more zombie blobs]
   -24> 2021-04-08T19:48:19.323+0200 7f0238a2ed80 -1 bluestore(/var/lib/ceph/osd/ceph-90) fsck error: 6#10:e55ce554:dumpsite::rbd_data.6.28423ad8f48ca1.00000000017e7410:head# - 1 zombie spanning blob(s) found, the first one: Blob(0x559eb277ce60 spanning 2 blob([!~30000] csum crc32c/0
x1000) use_tracker(0x3*0x10000 0x[0,0,0]) SharedBlob(0x559eb277c530 sbid 0x0))
   -23> 2021-04-08T19:48:19.323+0200 7f0238a2ed80  0 bluestore(/var/lib/ceph/osd/ceph-90) _fsck_check_objects partial offload, done myself 134108 of 1017671objects, threads 1
   -22> 2021-04-08T19:48:19.331+0200 7f0238a2ed80  1 bluestore(/var/lib/ceph/osd/ceph-90) _fsck_on_open checking shared_blobs
   -21> 2021-04-08T19:48:19.387+0200 7f0227a37700  5 prioritycache tune_memory target: 2147483648 mapped: 1714405376 unmapped: 5177344 heap: 1719582720 old mem: 1020054729 new mem: 1020054729
   -20> 2021-04-08T19:48:20.391+0200 7f0227a37700  5 prioritycache tune_memory target: 2147483648 mapped: 1712783360 unmapped: 6799360 heap: 1719582720 old mem: 1020054729 new mem: 1020054729
   -19> 2021-04-08T19:48:21.215+0200 7f0238a2ed80  1 bluestore(/var/lib/ceph/osd/ceph-90) _fsck_on_open checking pool_statfs
   -18> 2021-04-08T19:48:21.215+0200 7f0238a2ed80  5 bluestore(/var/lib/ceph/osd/ceph-90) _fsck_on_open marking per_pool_omap=1
   -17> 2021-04-08T19:48:21.215+0200 7f0238a2ed80  5 bluestore(/var/lib/ceph/osd/ceph-90) _fsck_on_open applying repair results
   -16> 2021-04-08T19:48:21.359+0200 7f0238a2ed80 -1 rocksdb: submit_common error: Corruption: unknown WriteBatch tag code = 2 Rocksdb transaction: 
Put( Prefix = O key = 0x80800000000000000a20a017eb64756d'psite!rbd_data.6.28423ad8f48ca1.000000000153d8bd!='0xfffffffffffffffeffffffffffffffff'o' Value size = 442)
Put( Prefix = O key = 0x80800000000000000a20a023e264756d'psite!rbd_data.6.28423ad8f48ca1.000000000133fc02!='0xfffffffffffffffeffffffffffffffff'o' Value size = 2622)
Put( Prefix = O key = 0x80800000000000000a20a02e'?dumpsite!rbd_data.6.28423ad8f48ca1.00000000019e2a6d!='0xfffffffffffffffeffffffffffffffff'o' Value size = 2198)
[... more transaction Put values ...]
   -15> 2021-04-08T19:48:21.359+0200 7f0238a2ed80  5 bluestore(/var/lib/ceph/osd/ceph-90) _fsck_on_open repair applied
   -14> 2021-04-08T19:48:21.359+0200 7f0238a2ed80  2 bluestore(/var/lib/ceph/osd/ceph-90) _fsck_on_open 1017671 objects, 233150 of them sharded.  
   -13> 2021-04-08T19:48:21.359+0200 7f0238a2ed80  2 bluestore(/var/lib/ceph/osd/ceph-90) _fsck_on_open 5525145 extents to 5275685 blobs, 257172 spanning, 322925 shared.
[... boot continues and crashes as in the top post ...]

So it's not a threading issue, ok.

I have plenty more OSDs to try, lol.

btw the "repair applied" success result is obviously wrong, I've already fixed that in https://github.com/ceph/ceph/pull/40444

Ok, some new information, tested on 15.2.11 :D

It seems that the OSDs are shredded with the ceph-osd boot-time fsck, but not with the ceph-bluestore-tool.

sudo ceph-bluestore-tool --path /var/lib/ceph/osd/ceph-121 --command repair

So maybe there's some subtle difference between the bluestoretool and ceph-osd? The most obvious difference is repair vs quickfix. So let's try to run:

sudo ceph-bluestore-tool --path /var/lib/ceph/osd/ceph-92 --command quick-fix

This hangs in the main thread at 100% load (two ShallowFSCK threads at 0%).

#0  0x00007ffff7b85620 in tcmalloc::PageHeap::AllocLarge(unsigned long) () from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#1  0x00007ffff7b85e4f in tcmalloc::PageHeap::New(unsigned long) () from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#2  0x00007ffff7b847bf in tcmalloc::CentralFreeList::Populate() () from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#3  0x00007ffff7b849c8 in tcmalloc::CentralFreeList::FetchFromOneSpansSafe(int, void**, void**) ()   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#4  0x00007ffff7b84abf in tcmalloc::CentralFreeList::RemoveRange(void**, void**, int) () from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#5  0x00007ffff7b87a5a in tcmalloc::ThreadCache::FetchFromCentralCache(unsigned long, unsigned long) ()   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#6  0x00007ffff7b9895b in tc_newarray () from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#7  0x0000555556149e18 in rocksdb::AllocateBlock(unsigned long, rocksdb::MemoryAllocator*) ()
#8  0x000055555614afd2 in rocksdb::BlockFetcher::PrepareBufferForBlockFromFile() ()
#9  0x000055555614869a in rocksdb::BlockFetcher::ReadBlockContents() ()
#10 0x000055555612f230 in rocksdb::BlockBasedTable::MaybeReadBlockAndLoadToCache(rocksdb::FilePrefetchBuffer*, rocksdb::BlockBasedTable::Rep*, rocksdb::ReadOptions const&, rocksdb::BlockHandle const&, rocksdb::UncompressionDict const&, rocksdb::BlockBasedTable::CachableEntry<rocksdb::Block>*, bool, rocksdb::GetContext*) ()
#11 0x000055555613e04f in rocksdb::DataBlockIter* rocksdb::BlockBasedTable::NewDataBlockIterator<rocksdb::DataBlockIter>(rocksdb::BlockBasedTable::Rep*, rocksdb::ReadOptions const&, rocksdb::BlockHandle const&, rocksdb::DataBlockIter*, bool, bool, bool, rocksdb::GetContext*, rocksdb::Status, rocksdb::FilePrefetchBuffer*) ()
#12 0x0000555556146cde in rocksdb::BlockBasedTableIterator<rocksdb::DataBlockIter, rocksdb::Slice>::InitDataBlock() ()
#13 0x0000555556146e85 in rocksdb::BlockBasedTableIterator<rocksdb::DataBlockIter, rocksdb::Slice>::FindKeyForward() ()
#14 0x000055555614594e in rocksdb::BlockBasedTableIterator<rocksdb::DataBlockIter, rocksdb::Slice>::Next() ()
#15 0x000055555607efd8 in rocksdb::IteratorWrapperBase<rocksdb::Slice>::Next() ()
#16 0x000055555605d231 in rocksdb::(anonymous namespace)::LevelIterator::Next() ()
#17 0x000055555607efd8 in rocksdb::IteratorWrapperBase<rocksdb::Slice>::Next() ()
#18 0x0000555556157d23 in rocksdb::MergingIterator::Next() ()
#19 0x0000555555fc090a in rocksdb::DBIter::Next() ()
#20 0x0000555555fc9e7e in rocksdb::ArenaWrappedDBIter::Next() ()
#21 0x0000555555ec852e in RocksDBStore::RocksDBWholeSpaceIteratorImpl::next() () at ./src/kv/RocksDBStore.cc:1377
#22 0x0000555555cf2025 in KeyValueDB::PrefixIteratorImpl::next (this=<optimized out>) at /usr/include/c++/9/bits/shared_ptr_base.h:1020
#23 BlueStore::_fsck_check_objects(BlueStore::FSCKDepth, BlueStore::FSCK_ObjectCtx&) () at ./src/os/bluestore/BlueStore.cc:8237
#24 0x0000555555cf6924 in BlueStore::_fsck_on_open(BlueStore::FSCKDepth, bool) () at ./src/os/bluestore/BlueStore.cc:8711
#25 0x0000555555d02326 in BlueStore::_fsck(BlueStore::FSCKDepth, bool) () at ./src/os/bluestore/BlueStore.cc:8546
#26 0x0000555555c03f12 in BlueStore::quick_fix (this=0x7fffffffadc0) at ./src/os/bluestore/BlueStore.h:2526
#27 main () at ./src/os/bluestore/bluestore_tool.cc:432
#28 0x00007fffece2abf7 in __libc_start_main (main=0x555555c02a60 <main>, argc=5, argv=0x7fffffffe988, init=<optimized out>,    fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffe978) at ../csu/libc-start.c:310
#29 0x0000555555c0b29a in _start () at /usr/include/c++/9/bits/char_traits.h:335

Tested several times, it hangs. After killing this, the bluestoretool repair did succeed though, and the OSD was de-zombie-blobbed, and works like it should.

So: It seems to be quick-fix vs repair? At least with bluestoretool-quickfix it didn't shred, so far.

FTR, Igor replied on the ML:

I think the root cause is related to the high amount of repairs made
during the first post-upgrade fsck run.

The check (and fix) for zombie spanning blobs was been backported to
v15.2.9 (here is the PR https://github.com/ceph/ceph/pull/39256). And I
presumt it's the one which causes BlueFS data corruption due to huge
transaction happening during such a repair.

I haven't seen this exact issue (as having that many zombie blobs is a
rarely met bug by itself) but we had to some degree similar issue with
upgrading omap names, see: https://github.com/ceph/ceph/pull/39377

Huge resulting transaction could cause too big write to WAL which in
turn caused data corruption (see https://github.com/ceph/ceph/pull/39701)

Although the fix for the latter has been merged for 15.2.10 some
additional issues with huge transactions might still exist...

If someone can afford another OSD loss it could be interesting to get an
OSD log for such a repair with debug-bluefs set to 20...

I'm planning to make a fix to cap transaction size for repair in the
nearest future anyway though..

Igor is there a tracker for that "cap transaction size for repair" ?

Jonas could you provide a log of repair with `debug_bluefs = 20` ?

Jonas, looks like my https://tracker.ceph.com/issues/48216#note-3 ?
This cluster have a EC meta pool for RBD?
Also, the repair:

sudo ceph-bluestore-tool --path /var/lib/ceph/osd/ceph-121 --command repair

Checked on next host by myself - "--command repair" fix OSD's before Nautilus auto fsck, and also CAN repair already broken OSD's (but not always)

Yes, this de-zombie-blobs the OSDs. So now I have an upgradepath by (automatically) stopping an osd, running bluestoretool-repair, and then starting it with ceph 15. To be sure I disabled the quickfsck-on-boot for now.

bluestoretool couldn't repair the broken OSDs, the rocksdb won't open since its journal is corrupted.

Konstantin: I had the zombie spanning-blobs for ec data pools used by cephfs and rbd.

Igor: Do you know why the boot-quickfix fails, but the bluestoretool repair works (as in not corrupting rocksdb)? Shouldn't that be the same mechanism?

I'd like to avoid losing more OSDs at the moment, but if you're gonna invest time, I can run a debug-bluefs-20 quickfix-crash again (wondering though why bluefs20 would provide any hint since it seems to be uninvolved, rather the fault is in repair+rocksdb?).

Jonas Jelten wrote:

Yes, this de-zombie-blobs the OSDs. So now I have an upgradepath by (automatically) stopping an osd, running bluestoretool-repair, and then starting it with ceph 15. To be sure I disabled the quickfsck-on-boot for now.

bluestoretool couldn't repair the broken OSDs, the rocksdb won't open since its journal is corrupted.

Konstantin: I had the zombie spanning-blobs for ec data pools used by cephfs and rbd.

Igor: Do you know why the boot-quickfix fails, but the bluestoretool repair works (as in not corrupting rocksdb)? Shouldn't that be the same mechanism?

One notable difference between repair and quick-fix is that the latter is multithreaded. By default 'bluestore_fsck_quick_fix_threads' parameter specifies two threads to perform checking. So one can verify the hypothesis by setting it to 1 and running a quick-fix.

Another difference is the narrower checking scope for quick-fix but I doubt this has that bad impact.

I'd like to avoid losing more OSDs at the moment, but if you're gonna invest time, I can run a debug-bluefs-20 quickfix-crash again (wondering though why bluefs20 would provide any hint since it seems to be uninvolved, rather the fault is in repair+rocksdb?).

Perhaps we can postpone that for a bit - hopefully I'll have time to try to reproduce the issue in my lab next week. Looks like this should be doable...
If this wouldn't succeeded then we can go back to the idea to dissect one of your OSDs.

Added nautilus to backports, because if upgrade from luminous release, flow is luminous->nautilus->pacific.

Konstantin Shalygin wrote:

Added nautilus to backports, because if upgrade from luminous release, flow is luminous->nautilus->pacific.

yep, missed that quick-fix is in Nautilus too..