Project

General

Profile

Actions
Copy link

Bug #52939

closed

lockdep cycle under BlueFS::_compact_log_async_LD_NF_D()

Added by Casey Bodley over 2 years ago. Updated over 2 years ago.

Status:
Rejected
Priority:
High
Assignee:
Adam Kupczyk
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
Yes
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
43794
Crash signature (v1):
Crash signature (v2):

Description

reproduces reliably in vstart just after starting s3-tests against rgw on master, at commit c19250ce3cb30a5a0409e3ebd4142dad6191642e

   -43> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs _clear_dirty_set_stable_D seq_stable 4097
   -42> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_init
   -41> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 38 size 0xae30 mtime 2021-10-14T13:52:36.809287-0400 allocated 100000 extents [1:0xc00000~100000])
   -40> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 37 size 0x1894e2a mtime 2021-10-14T13:53:48.401110-0400 allocated 1900000 extents [0:0x500000~1000000,0:0x1900000~300000,0:0x2000000~300000,0:0x2700000~200000,0:0x2d00000~100000])
   -39> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 36 size 0x10 mtime 2021-10-14T13:52:36.805830-0400 allocated 100000 extents [1:0xb00000~100000])
   -38> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 35 size 0x475 mtime 2021-10-14T13:52:36.805243-0400 allocated 100000 extents [1:0xa00000~100000])
   -37> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 33 size 0x4a6 mtime 2021-10-14T13:52:36.803329-0400 allocated 100000 extents [1:0x700000~100000])
   -36> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 28 size 0xae30 mtime 2021-10-14T13:52:32.561061-0400 allocated 100000 extents [1:0x800000~100000])
   -35> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 29 size 0x0 mtime 2021-10-14T13:52:36.815800-0400 allocated 100000 extents [1:0x900000~100000])
   -34> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 21 size 0x3a mtime 2021-10-14T13:52:29.076036-0400 allocated 100000 extents [1:0x1200000~100000])
   -33> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 24 size 0x599 mtime 2021-10-14T13:52:32.556185-0400 allocated 100000 extents [1:0x500000~100000])
   -32> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 2 size 0x0 mtime 2021-10-14T13:52:29.002203-0400 allocated 0 extents [])
   -31> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 3 size 0x25 mtime 2021-10-14T13:52:29.002664-0400 allocated 100000 extents [1:0x100000~100000])
   -30> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 32 size 0x4e2 mtime 2021-10-14T13:52:36.802331-0400 allocated 100000 extents [1:0x400000~100000])
   -29> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create ALLOCATOR_NCB_DIR
   -28> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link ALLOCATOR_NCB_DIR/ALLOCATOR_NCB_FILE to 29
   -27> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create db
   -26> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/000029.sst to 24
   -25> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/000035.sst to 32
   -24> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/000036.sst to 33
   -23> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/CURRENT to 36
   -22> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/IDENTITY to 3
   -21> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/LOCK to 2
   -20> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/MANIFEST-000038 to 35
   -19> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/OPTIONS-000033 to 28
   -18> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/OPTIONS-000041 to 38
   -17> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create db.slow
   -16> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create db.wal
   -15> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db.wal/000039.log to 37
   -14> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create sharding
   -13> 2021-10-14T13:53:48.401-0400 7f3934723640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link sharding/def to 21
   -12> 2021-10-14T13:53:48.401-0400 7f3934723640 10 bluefs _allocate len 0x100000 from 1
   -11> 2021-10-14T13:53:48.401-0400 7f3934723640 10 HybridAllocator allocate want 0x100000 unit 0x100000 max_alloc_size 0x100000 hint 0x0
   -10> 2021-10-14T13:53:48.401-0400 7f3934723640 20 AvlAllocator _allocate first fit=13631488 size=1048576
    -9> 2021-10-14T13:53:48.401-0400 7f3934723640 10 bluefs _pad_bl padding with 0xc38 zeros
    -8> 2021-10-14T13:53:48.401-0400 7f3934723640 10 bluefs _compact_log_async_LD_NF_D new_log_jump_to 0x100000
    -7> 2021-10-14T13:53:48.401-0400 7f3934723640  0
------------------------------------
existing dependency BlueFS::FileWriter::lock (168) -> BlueFS::File::lock (167) at:

    -6> 2021-10-14T13:53:48.409-0400 7f3934723640  0 new dependency BlueFS::File::lock (167) -> BlueFS::FileWriter::lock (168) creates a cycle at
 ceph version Development (no_version) quincy (dev)
 1: (ceph::mutex_debug_detail::mutex_debug_impl<false>::lock(bool)+0x2e) [0x5586b4f4d860]
 2: (BlueFS::_compact_log_async_LD_NF_D()+0x9ec) [0x5586b56c2b9a]
 3: (BlueFS::_maybe_compact_log_LN_NF_LD_D()+0x38) [0x5586b56c9808]
 4: (BlueFS::fsync(BlueFS::FileWriter*)+0x4f3) [0x5586b56ca0c5]
 5: (BlueRocksWritableFile::Sync()+0x11) [0x5586b56d9921]
 6: (rocksdb::LegacyWritableFileWrapper::Sync(rocksdb::IOOptions const&, rocksdb::IODebugContext*)+0x3f) [0x5586b5c14459]
 7: (rocksdb::WritableFileWriter::SyncInternal(bool)+0x257) [0x5586b5e1bfab]
 8: (rocksdb::WritableFileWriter::Sync(bool)+0x192) [0x5586b5e1b96e]
 9: (rocksdb::DBImpl::WriteToWAL(rocksdb::WriteThread::WriteGroup const&, rocksdb::log::Writer*, unsigned long*, bool, bool, unsigned long)+0x389) [0x5586b5c6862b]
 10: (rocksdb::DBImpl::WriteImpl(rocksdb::WriteOptions const&, rocksdb::WriteBatch*, rocksdb::WriteCallback*, unsigned long*, unsigned long, bool, unsigned long*, unsigned long, rocksdb::PreReleaseCallback*)+0x12de) [0x5586b5c642a8]
 11: (rocksdb::DBImpl::Write(rocksdb::WriteOptions const&, rocksdb::WriteBatch*)+0x4a) [0x5586b5c62f66]
 12: (RocksDBStore::submit_common(rocksdb::WriteOptions&, std::shared_ptr<KeyValueDB::TransactionImpl>)+0x7c) [0x5586b5bb41c0]
 13: (RocksDBStore::submit_transaction_sync(std::shared_ptr<KeyValueDB::TransactionImpl>)+0xaf) [0x5586b5bb5545]
 14: (BlueStore::_kv_sync_thread()+0x2ebd) [0x5586b55f96cd]
 15: (BlueStore::KVSyncThread::entry()+0xd) [0x5586b56331b3]
 16: (Thread::entry_wrapper()+0x3f) [0x5586b5755543]
 17: (Thread::_entry_func(void*)+0x9) [0x5586b575555b]
 18: /lib64/libpthread.so.0(+0x93f9) [0x7f394902d3f9]
 19: clone()
    -5> 2021-10-14T13:53:48.410-0400 7f3934723640  0 btw, i am holding these locks:
    -4> 2021-10-14T13:53:48.410-0400 7f3934723640  0   BlueFS::File::lock (167)
    -3> 2021-10-14T13:53:48.410-0400 7f3934723640  0   BlueFS::FileWriter::lock (168)
    -2> 2021-10-14T13:53:48.410-0400 7f3934723640  0
    -1> 2021-10-14T13:53:48.418-0400 7f3934723640 -1 ../src/common/lockdep.cc: In function 'int lockdep_will_lock(const char*, int, bool, bool)' thread 7f3934723640 time 2021-10-14T13:53:48.410701-0400
../src/common/lockdep.cc: 337: ceph_abort_msg("abort() called")
Actions
Copy link
 #1

Updated by Igor Fedotov over 2 years ago

@Casey, as far as I understand this one is included in your build: https://github.com/ceph/ceph/pull/42099

Could you please revert it and try to reproduce again?

Actions
Copy link
 #2

Updated by Casey Bodley over 2 years ago

Igor Fedotov wrote:

@Casey, as far as I understand this one is included in your build: https://github.com/ceph/ceph/pull/42099

Could you please revert it and try to reproduce again?

sure, thanks

Actions
Copy link
 #3

Updated by Casey Bodley over 2 years ago

update: the same vstart test workload is running stably with the commits from that pr reverted

git revert 22c09dee82084e974489b8a4cd19b238f2f2593b \
13b637c32e29ff99b7a0a4596c71fd1f722c26aa \
aa9dbdd8e8a31fc1c233b30fde39a995cdc1663c \
a5a0a74a254eb5de16f87c9a199d3437304aa58a \
d482ed16b5a2ddfc22b06a33348fab66be5ed2ca \
9ad938f8156e57e0b4073d5718cd8dabab07f691 \
f833b461ad6f180838a0682019417abcfd9103b8 \
45b3c5d0ea6c737ae6bf742387f5746b65eeb88d \
08cf6d04a198a8dec3fc920a180208742c6fc965 \
6b6a76a961db949c222de72f8fd5203ffac450d0 \
f83e0ac544a77440b538b0be303b3859125915dd

Actions
Copy link
 #4

Updated by Igor Fedotov over 2 years ago

  • Assignee set to Adam Kupczyk

@Adam DC949, would you take a look, please?

Actions
Copy link
 #5

Updated by Kefu Chai over 2 years ago

  • Regression changed from No to Yes
Actions
Copy link
 #6

Updated by Kefu Chai over 2 years ago

  • Priority changed from Normal to High
Actions
Copy link
 #7

Updated by Adam Kupczyk over 2 years ago

  • Pull request ID set to 43589
Actions
Copy link
 #8

Updated by Adam Kupczyk over 2 years ago

  • Status changed from New to Fix Under Review
Actions
Copy link
 #9

Updated by Casey Bodley over 2 years ago

i tested with the fix from https://github.com/ceph/ceph/pull/43589 (commit 4b23ecfa2967d1df37562c67df028b5ce1700afb), on top of the same commit c19250ce3cb30a5a0409e3ebd4142dad6191642e as before, and saw a different lockdep failure:

2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_init
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 38 size 0xae30 mtime 2021-10-19T09:25:19.672092-0400 allocated 100000 extents [1:0xc00000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 37 size 0x187dfee mtime 2021-10-19T09:25:54.350472-0400 allocated 1900000 extents [0:0x500000~1000000,0:0x1900000~300000,0:0x2000000~200000,0:0x2600000~300000,0:0x2d00000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 36 size 0x10 mtime 2021-10-19T09:25:19.668849-0400 allocated 100000 extents [1:0xb00000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 35 size 0x475 mtime 2021-10-19T09:25:19.668252-0400 allocated 100000 extents [1:0xa00000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 33 size 0x4a6 mtime 2021-10-19T09:25:19.666506-0400 allocated 100000 extents [1:0x700000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 28 size 0xae30 mtime 2021-10-19T09:25:15.404158-0400 allocated 100000 extents [1:0x800000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 29 size 0x0 mtime 2021-10-19T09:25:19.678315-0400 allocated 100000 extents [1:0x900000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 21 size 0x3a mtime 2021-10-19T09:25:11.931067-0400 allocated 100000 extents [1:0x1200000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 24 size 0x599 mtime 2021-10-19T09:25:15.398816-0400 allocated 100000 extents [1:0x500000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 2 size 0x0 mtime 2021-10-19T09:25:11.853803-0400 allocated 0 extents [])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 3 size 0x25 mtime 2021-10-19T09:25:11.854667-0400 allocated 100000 extents [1:0x100000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_file_update file(ino 32 size 0x4e2 mtime 2021-10-19T09:25:19.665384-0400 allocated 100000 extents [1:0x400000~100000])
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create ALLOCATOR_NCB_DIR
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link ALLOCATOR_NCB_DIR/ALLOCATOR_NCB_FILE to 29
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create db
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/000029.sst to 24
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/000035.sst to 32
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/000036.sst to 33
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/CURRENT to 36
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/IDENTITY to 3
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/LOCK to 2
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/MANIFEST-000038 to 35
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/OPTIONS-000033 to 28
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db/OPTIONS-000041 to 38
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create db.slow
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create db.wal
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link db.wal/000039.log to 37
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_create sharding
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 bluefs compact_log_async_dump_metadata_NF op_dir_link sharding/def to 21
2021-10-19T09:25:54.350-0400 7f7d2692a640 10 bluefs _allocate len 0x100000 from 1
2021-10-19T09:25:54.350-0400 7f7d2692a640 10 HybridAllocator allocate want 0x100000 unit 0x100000 max_alloc_size 0x100000 hint 0x0
2021-10-19T09:25:54.350-0400 7f7d2692a640 20 AvlAllocator _allocate first fit=13631488 size=1048576
2021-10-19T09:25:54.350-0400 7f7d2692a640 10 bluefs _pad_bl padding with 0xc38 zeros
2021-10-19T09:25:54.350-0400 7f7d2692a640 10 bluefs _compact_log_async_LD_NF_D new_log_jump_to 0x100000
2021-10-19T09:25:54.350-0400 7f7d2a932640 20 bluestore.MempoolThread(0x55a4b8b81ec8) _resize_shards cache_size: 2845415832 kv_alloc: 1207959552 kv_used: 1200 kv_onode_alloc: 167772160 kv_onode_used: 472 meta_alloc: 1207959552 meta_used: 3495564 data_alloc: 218103808 data_used: 184320
2021-10-19T09:25:54.350-0400 7f7d2692a640  0
recursive lock of BlueFS::FileWriter::lock (168)
 ceph version Development (no_version) quincy (dev)
 1: (ceph::mutex_debug_detail::mutex_debug_impl<false>::lock(bool)+0x2e) [0x55a4b5b87860]
 2: (BlueFS::_compact_log_async_LD_NF_D()+0x9ac) [0x55a4b62fcb5a]
 3: (BlueFS::_maybe_compact_log_LN_NF_LD_D()+0x38) [0x55a4b6303804]
 4: (BlueFS::fsync(BlueFS::FileWriter*)+0x4f3) [0x55a4b63040c1]
 5: (BlueRocksWritableFile::Sync()+0x11) [0x55a4b631391d]
 6: (rocksdb::LegacyWritableFileWrapper::Sync(rocksdb::IOOptions const&, rocksdb::IODebugContext*)+0x3f) [0x55a4b684e455]
 7: (rocksdb::WritableFileWriter::SyncInternal(bool)+0x257) [0x55a4b6a55fa7]
 8: (rocksdb::WritableFileWriter::Sync(bool)+0x192) [0x55a4b6a5596a]
 9: (rocksdb::DBImpl::WriteToWAL(rocksdb::WriteThread::WriteGroup const&, rocksdb::log::Writer*, unsigned long*, bool, bool, unsigned long)+0x389) [0x55a4b68a2627]
 10: (rocksdb::DBImpl::WriteImpl(rocksdb::WriteOptions const&, rocksdb::WriteBatch*, rocksdb::WriteCallback*, unsigned long*, unsigned long, bool, unsigned long*, unsigned long, rocksdb::PreReleaseCallback*)+0x12de) [0x55a4b689e2a4]
 11: (rocksdb::DBImpl::Write(rocksdb::WriteOptions const&, rocksdb::WriteBatch*)+0x4a) [0x55a4b689cf62]
 12: (RocksDBStore::submit_common(rocksdb::WriteOptions&, std::shared_ptr<KeyValueDB::TransactionImpl>)+0x7c) [0x55a4b67ee1bc]
 13: (RocksDBStore::submit_transaction_sync(std::shared_ptr<KeyValueDB::TransactionImpl>)+0xaf) [0x55a4b67ef541]
 14: (BlueStore::_kv_sync_thread()+0x2ebd) [0x55a4b62336cd]
 15: (BlueStore::KVSyncThread::entry()+0xd) [0x55a4b626d1b3]
 16: (Thread::entry_wrapper()+0x3f) [0x55a4b638f53f]
 17: (Thread::_entry_func(void*)+0x9) [0x55a4b638f557]
 18: /lib64/libpthread.so.0(+0x93f9) [0x7f7d3b2343f9]
 19: clone()
Actions
Copy link
 #10

Updated by Casey Bodley over 2 years ago

steps to reproduce:

~/ceph/build $ MON=1 OSD=1 RGW=1 MGR=0 MDS=0 ../src/vstart.sh -n -d
~/ceph/build $ ../qa/workunits/rgw/run-s3tests.sh
Actions
Copy link
 #11

Updated by Neha Ojha over 2 years ago

  • Pull request ID changed from 43589 to 43794
Actions
Copy link
 #12

Updated by Neha Ojha over 2 years ago

  • Status changed from Fix Under Review to Rejected

The fix will be merged in https://github.com/ceph/ceph/pull/43794, not a bug at this time.

Actions
Copy link

Also available in: Atom PDF