Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[docdb] Various race conditions when doing concurrent TRUNCATE and write operations #3288

Closed
bmatican opened this issue Jan 8, 2020 · 7 comments
Assignees
Labels
area/docdb YugabyteDB core features kind/failing-test Tests and testing infra priority/high High Priority

Comments

@bmatican
Copy link
Contributor

bmatican commented Jan 8, 2020

When executing concurrent write and truncate operations, we have noticed several potential race conditions, leading to SEGVs on accessing null pointers. Describing these below:

  1. During Truncate, the Tablet code will shutdown rocksdb, reset its unique_ptr and re-create it. However, the Tablet also sets up a background listener callback through ListenFilesChanged. Due to [docdb] Rocksdb shutdown code does not wait for all pending flushes #3476, it is possible that the rocksdb we are closing is currently flushing/compacting a file, and, when the file is created and the callback has to be called, our rocksdb instance has already been destroyed.

To address this situation, we consider the following:

  • During both Truncate and Shutdown, before destroying the rocksdb instance, we can first reset the listener we have setup. This should prevent calling back code on an invalid object.
  • We already have a mechanism to disable flush on shutdown (for cases when we drop the table). We can extend this to truncate as well, as we know we will not need any of these rocksdb files!
  • Finally, we should standalone investigate [docdb] Rocksdb shutdown code does not wait for all pending flushes #3476, as it's possible that there are further complications of this, or that we might end up with some in the future.
  1. On the leader write path, when calling AcquireLocksAndPerformDocOperations-> StartDocWriteOperation, we eventually require accessing the intents rocksdb for resolving conflicts. However, this path does not leverage the pending_op_counter_, which is what we currently use to ensure we do not operate on invalid state.

  2. We also noticed a race condition on followers, between processing write operations (checking rocksdb::NeedsDelay) and applying truncate operations (essentially resetting the rocksdb instance). This requires further investigation into our async model of processing and applying operations, so have filed [docdb] Investigate raft race between incoming write operations and background applies #3477. For now, we can use the same pending_op_counter_ mechanism to ensure that the call to Tablet::ShouldApplyWrite is similarly serialized, like above.

@bmatican bmatican added kind/failing-test Tests and testing infra area/docdb YugabyteDB core features labels Jan 8, 2020
@bmatican bmatican self-assigned this Jan 8, 2020
@bmatican bmatican assigned rajukumaryb and unassigned bmatican Jan 10, 2020
@bmatican
Copy link
Contributor Author

See for the user setup test case (in Java): https://github.com/lhotari/yugabyte-bugs-repro/blob/master/src/test/java/com/github/lhotari/dbcontainer/yugabyte/truncatetable/AbstractTruncateTableCrashBugTest.java

We should probably port this into our test suite as well and confirm it repros, as expected! Should make it far easier to debug and fix then!

@bmatican bmatican added the priority/high High Priority label Jan 15, 2020
@rajukumaryb
Copy link
Contributor

Another stack seen with same workload -

#0  0x000056371c706b00 in ?? ()
#1  0x00007f5229291099 in std::__invoke_impl<void, void (yb::tablet::Tablet::*&)(), yb::tablet::Tablet*&> (__t=<optimized out>, __f=<optimized out>) at /usr/include/c++/7/bits/invoke.h:73
#2  std::__invoke<void (yb::tablet::Tablet::*&)(), yb::tablet::Tablet*&> (__fn=<optimized out>) at /usr/include/c++/7/bits/invoke.h:95
#3  std::_Bind<void (yb::tablet::Tablet::*(yb::tablet::Tablet*))()>::__call<void, , 0ul>(std::tuple<>&&, std::_Index_tuple<0ul>) (__args=..., this=<optimized out>) at /usr/include/c++/7/functional:467
#4  std::_Bind<void (yb::tablet::Tablet::*(yb::tablet::Tablet*))()>::operator()<, void>() (this=<optimized out>) at /usr/include/c++/7/functional:551
#5  std::_Function_handler<void (), std::_Bind<void (yb::tablet::Tablet::*(yb::tablet::Tablet*))()> >::_M_invoke(std::_Any_data const&) (__functor=...) at /usr/include/c++/7/bits/std_function.h:316
#6  0x00007f5225aee92c in std::function<void ()>::operator()() const (this=0x56371c5534f0) at /usr/include/c++/7/bits/std_function.h:706
#7  rocksdb::DBImpl::FilesChanged (this=this@entry=0x56371c552b00) at ../../src/yb/rocksdb/db/db_impl.cc:4359
#8  0x00007f5225b14b1b in rocksdb::DBImpl::BackgroundCallFlush (this=this@entry=0x56371c552b00, cfd=cfd@entry=0x0) at ../../src/yb/rocksdb/db/db_impl.cc:3285
#9  0x00007f5225b14c8e in rocksdb::DBImpl::BGWorkFlush (db=0x56371c552b00) at ../../src/yb/rocksdb/db/db_impl.cc:3136
#10 0x00007f5225c5f673 in rocksdb::ThreadPool::BGThread (this=0x563719aeeee0, thread_id=0) at ../../src/yb/rocksdb/util/thread_posix.cc:126
#11 0x00007f5225c5f7e5 in rocksdb::ThreadPool::<lambda()>::operator() (__closure=<optimized out>) at ../../src/yb/rocksdb/util/thread_posix.cc:165
#12 std::_Function_handler<void(), rocksdb::ThreadPool::StartBGThreads()::<lambda()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /usr/include/c++/7/bits/std_function.h:316
#13 0x00007f5222327e55 in std::function<void ()>::operator()() const (this=0x56371c684a78) at /usr/include/c++/7/bits/std_function.h:706
#14 yb::Thread::SuperviseThread (arg=0x56371c684a20) at ../../src/yb/util/thread.cc:739
#15 0x00007f521cfd36db in start_thread (arg=0x7f51f6aeb700) at pthread_create.c:463
#16 0x00007f521ccfc88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

@rajukumaryb
Copy link
Contributor

Original race condition stack -

 #0  0x00007f56b6bce33e in yb::docdb::BoundedRocksDbIterator::BoundedRocksDbIterator (this=0x7f562f2d0fd0, rocksdb=0x0, read_opts=..., key_bounds=0x55fd7430df00) at ../../src/yb/docdb/bounded_rocksdb_iterator.cc:22
 #1  0x00007f56b6c20bc2 in yb::docdb::CreateRocksDBIterator (rocksdb=0x0, docdb_key_bounds=0x55fd7430df00, bloom_filter_mode=bloom_filter_mode@entry=yb::docdb::BloomFilterMode::DONT_USE_BLOOM_FILTER, user_key_for_filter=..., query_id=query_id@entry=0, file_filter=std::shared_ptr<rocksdb::ReadFileFilter> (empty) = {...}, iterate_upper_bound=0x7f562f2d18a0)        at ../../src/yb/docdb/docdb_rocksdb_util.cc:380
 #2  0x00007f56b6bd68c4 in yb::docdb::(anonymous namespace)::ConflictResolver::EnsureIntentIteratorCreated (this=0x7f562f2d1850) at ../../src/yb/docdb/conflict_resolution.cc:200
 #3  yb::docdb::(anonymous namespace)::ConflictResolver::ReadIntentConflicts (this=this@entry=0x7f562f2d1850, type=..., type@entry=..., intent_key_prefix=intent_key_prefix@entry=0x7f562f2d14f0) at ../../src/yb/docdb/conflict_resolution.cc:135
 #4  0x00007f56b6bd8466 in yb::docdb::(anonymous namespace)::TransactionConflictResolverContext::ProcessIntent (this=0x7f562f2d1980, resolver=0x7f562f2d1850, strong_intent_types=..., strength=<optimized out>, intent_key_prefix=0x7f562f2d14f0) at ../../src/yb/docdb/conflict_resolution.cc:502
 #5  0x00007f56b6bd136a in std::__invoke_impl<yb::Status, yb::Status (yb::docdb::(anonymous namespace)::TransactionConflictResolverContext::*&)(yb::docdb::(anonymous namespace)::ConflictResolver*, yb::EnumBitSet<yb::docdb::IntentType>, yb::docdb::IntentStrength, yb::docdb::KeyBytes*), yb::docdb::(anonymous namespace)::TransactionConflictResolverContext*&, yb::   docdb::(anonymous namespace)::ConflictResolver*&, yb::EnumBitSet<yb::docdb::IntentType>&, yb::docdb::IntentStrength, yb::docdb::KeyBytes*> (__t=<optimized out>, __f=<optimized out>) at /usr/include/c++/7/bits/invoke.h:73
 #6  std::__invoke<yb::Status (yb::docdb::(anonymous namespace)::TransactionConflictResolverContext::*&)(yb::docdb::(anonymous namespace)::ConflictResolver*, yb::EnumBitSet<yb::docdb::IntentType>, yb::docdb::IntentStrength, yb::docdb::KeyBytes*), yb::docdb::(anonymous namespace)::TransactionConflictResolverContext*&, yb::docdb::(anonymous namespace)::            ConflictResolver*&, yb::EnumBitSet<yb::docdb::IntentType>&, yb::docdb::IntentStrength, yb::docdb::KeyBytes*> (__fn=<optimized out>) at /usr/include/c++/7/bits/invoke.h:96
 #7  std::_Bind<yb::Status (yb::docdb::(anonymous namespace)::TransactionConflictResolverContext::*(yb::docdb::(anonymous namespace)::TransactionConflictResolverContext*, yb::docdb::(anonymous namespace)::ConflictResolver*, yb::EnumBitSet<yb::docdb::IntentType>, std::_Placeholder<1>, std::_Placeholder<3>))(yb::docdb::(anonymous namespace)::ConflictResolver*,     yb::EnumBitSet<yb::docdb::IntentType>, yb::docdb::IntentStrength, yb::docdb::KeyBytes*)>::__call<yb::Status, yb::docdb::IntentStrength&&, yb::Slice&&, yb::docdb::KeyBytes*&&, 0, 1, 2, 3, 4> (__args=..., this=<optimized out>) at /usr/include/c++/7/functional:469
 #8  std::_Bind<yb::Status (yb::docdb::(anonymous namespace)::TransactionConflictResolverContext::*(yb::docdb::(anonymous namespace)::TransactionConflictResolverContext*, yb::docdb::(anonymous namespace)::ConflictResolver*, yb::EnumBitSet<yb::docdb::IntentType>, std::_Placeholder<1>, std::_Placeholder<3>))(yb::docdb::(anonymous namespace)::ConflictResolver*,     yb::EnumBitSet<yb::docdb::IntentType>, yb::docdb::IntentStrength, yb::docdb::KeyBytes*)>::operator()<yb::docdb::IntentStrength, yb::Slice, yb::docdb::KeyBytes*> (this=<optimized out>) at /usr/include/c++/7/functional:551
 #9  boost::detail::function::function_obj_invoker3<std::_Bind<yb::Status (yb::docdb::(anonymous namespace)::TransactionConflictResolverContext::*(yb::docdb::(anonymous namespace)::TransactionConflictResolverContext*, yb::docdb::(anonymous namespace)::ConflictResolver*, yb::EnumBitSet<yb::docdb::IntentType>, std::_Placeholder<1>, std::_Placeholder<3>))(yb::      docdb::(anonymous namespace)::ConflictResolver*, yb::EnumBitSet<yb::docdb::IntentType>, yb::docdb::IntentStrength, yb::docdb::KeyBytes*)>, yb::Status, yb::docdb::IntentStrength, yb::Slice, yb::docdb::KeyBytes*>::invoke(boost::detail::function::function_buffer &, yb::docdb::IntentStrength, yb::Slice, yb::docdb::KeyBytes *) (function_obj_ptr=..., a0=<optimized    out>, a1=..., a2=<optimized out>) at ../../thirdparty/installed/uninstrumented/include/boost/function/function_template.hpp:137
 #10 0x00007f56b6bf8e9f in boost::function3<yb::Status, yb::docdb::IntentStrength, yb::Slice, yb::docdb::KeyBytes*>::operator() (a2=0x7f562f2d14f0, a1=..., a0=yb::docdb::IntentStrength::kWeak, this=0x7f562f2d16e0) at ../../thirdparty/installed/uninstrumented/include/boost/function/function_template.hpp:764
 #11 yb::docdb::(anonymous namespace)::EnumerateWeakIntents (key=..., functor=..., encoded_key_buffer=encoded_key_buffer@entry=0x7f562f2d14f0, partial_range_key_intents=..., partial_range_key_intents@entry=...) at ../../src/yb/docdb/docdb.cc:446
 #12 0x00007f56b6bf9706 in yb::docdb::EnumerateIntents(yb::Slice, yb::Slice const&, boost::function<yb::Status (yb::docdb::IntentStrength, yb::Slice, yb::docdb::KeyBytes*)> const&, yb::docdb::KeyBytes*, yb::StronglyTypedBool<yb::docdb::PartialRangeKeyIntents_Tag>) (key=..., intent_value=..., functor=..., encoded_key_buffer=encoded_key_buffer@                     entry=0x7f562f2d14f0, partial_range_key_intents=...) at ../../src/yb/docdb/docdb.cc:526
 #13 0x00007f56b6bf9a1f in yb::docdb::EnumerateIntents(google::protobuf::RepeatedPtrField<yb::docdb::KeyValuePairPB> const&, boost::function<yb::Status (yb::docdb::IntentStrength, yb::Slice, yb::docdb::KeyBytes*)> const&, yb::StronglyTypedBool<yb::docdb::PartialRangeKeyIntents_Tag>) (kv_pairs=..., functor=..., partial_range_key_intents=...,                       partial_range_key_intents@entry=...) at ../../src/yb/docdb/docdb.cc:540
 #14 0x00007f56b6bd37a2 in yb::docdb::(anonymous namespace)::TransactionConflictResolverContext::DoReadConflicts (resolver=0x7f562f2d1850, kind=yb::docdb::OperationKind::kRead, pairs=..., this=0x7f562f2d1980) at ../../src/yb/docdb/conflict_resolution.cc:440
 #15 yb::docdb::(anonymous namespace)::TransactionConflictResolverContext::ReadConflicts (this=0x7f562f2d1980, resolver=0x7f562f2d1850) at ../../src/yb/docdb/conflict_resolution.cc:421
 #16 0x00007f56b6bd7a94 in yb::docdb::(anonymous namespace)::ConflictResolver::Resolve (this=0x7f562f2d1850) at ../../src/yb/docdb/conflict_resolution.cc:129
 #17 yb::docdb::ResolveTransactionConflicts (doc_ops=std::vector of length 0, capacity 0, write_batch=..., hybrid_time=..., read_time=..., doc_db=..., partial_range_key_intents=..., status_manager=0x55fd74bb9ea0, conflicts_metric=0x55fd74753400) at ../../src/yb/docdb/conflict_resolution.cc:672
 #18 0x00007f56b76cb335 in yb::tablet::Tablet::StartDocWriteOperation (this=this@entry=0x55fd7430db00, operation=0x55fd7441b980) at ../../src/yb/tablet/tablet.cc:2035
 #19 0x00007f56b76cd820 in yb::tablet::Tablet::AcquireLocksAndPerformDocOperations (this=0x55fd7430db00, operation=std::unique_ptr<yb::tablet::WriteOperation> = {...}) at ../../src/yb/tablet/tablet.cc:1473
 #20 0x00007f56b76fb905 in yb::tablet::TabletPeer::WriteAsync (this=this@entry=0x55fd74c59b80, state=std::unique_ptr<yb::tablet::WriteOperationState> = {...}, term=term@entry=1, deadline=...) at ../../src/yb/tablet/tablet_peer.cc:556
 #21 0x00007f56b7f5093b in yb::tserver::TabletServiceImpl::Read (this=0x55fd72d96c80, req=<optimized out>, resp=0x55fd75299550, context=...) at ../../src/yb/tserver/tablet_service.cc:1396
 #22 0x00007f56b61268e2 in yb::tserver::TabletServerServiceIf::Handle (this=0x55fd72d96c80, call=...) at src/yb/tserver/tserver_service.service.cc:160
 #23 0x00007f56b20b588a in yb::rpc::ServicePoolImpl::Handle (this=0x55fd72d1dd40, incoming=std::shared_ptr<yb::rpc::InboundCall> (empty) = {...}) at ../../src/yb/rpc/service_pool.cc:262
 #24 0x00007f56b204ea0c in yb::rpc::InboundCall::InboundCallTask::Run (this=<optimized out>) at ../../src/yb/rpc/inbound_call.cc:212
 #25 0x00007f56b20c4d1f in yb::rpc::(anonymous namespace)::Worker::Execute (this=<optimized out>) at ../../src/yb/rpc/thread_pool.cc:99
 #26 0x00007f56b20c1330 in std::__invoke_impl<void, void (yb::rpc::(anonymous namespace)::Worker::*&)(), yb::rpc::(anonymous namespace)::Worker*&> (__t=<optimized out>, __f=<optimized out>) at /usr/include/c++/7/bits/invoke.h:73
 #27 std::__invoke<void (yb::rpc::(anonymous namespace)::Worker::*&)(), yb::rpc::(anonymous namespace)::Worker*&> (__fn=<optimized out>) at /usr/include/c++/7/bits/invoke.h:95
 #28 std::_Bind<void (yb::rpc::(anonymous namespace)::Worker::*(yb::rpc::(anonymous namespace)::Worker*))()>::__call<void, 0> (__args=..., this=<optimized out>) at /usr/include/c++/7/functional:467
 #29 std::_Bind<void (yb::rpc::(anonymous namespace)::Worker::*(yb::rpc::(anonymous namespace)::Worker*))()>::operator()<> (this=<optimized out>) at /usr/include/c++/7/functional:551
 #30 std::_Function_handler<void(), std::_Bind<void (yb::rpc::(anonymous namespace)::Worker::*(yb::rpc::(anonymous namespace)::Worker*))()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /usr/include/c++/7/bits/std_function.h:316
 #31 0x00007f56b076bde5 in std::function<void ()>::operator()() const (this=0x55fd74866dd8) at /usr/include/c++/7/bits/std_function.h:706
 #32 yb::Thread::SuperviseThread (arg=0x55fd74866d80) at ../../src/yb/util/thread.cc:739
 #33 0x00007f56ab4176db in start_thread (arg=0x7f562f2d3700) at pthread_create.c:463
 #34 0x00007f56ab14088f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

@rajukumaryb
Copy link
Contributor

Stack from TSAN test SnapshotTxnTest.MultiWriteWithRestart -

 Program terminated with signal SIGSEGV, Segmentation fault.
 #0  0x0000556bfef357a0 in ?? ()
 [Current thread is 1 (Thread 0x7fd66faa8700 (LWP 11020))]
 #0  0x0000556bfef357a0 in ?? ()
 #1  0x00007fd6a5995591 in std::__invoke_impl<void, void (yb::tablet::Tablet::*&)(), yb::tablet::Tablet*&> (__t=<optimized out>, __f=<optimized out>) at /usr/include/c++/7/bits/invoke.h:73
 #2  std::__invoke<void (yb::tablet::Tablet::*&)(), yb::tablet::Tablet*&> (__fn=<optimized out>) at /usr/include/c++/7/bits/invoke.h:95
 #3  std::_Bind<void (yb::tablet::Tablet::*(yb::tablet::Tablet*))()>::__call<void, , 0ul>(std::tuple<>&&, std::_Index_tuple<0ul>) (__args=..., this=<optimized out>) at /usr/include/c++/7/functional:467
 #4  std::_Bind<void (yb::tablet::Tablet::*(yb::tablet::Tablet*))()>::operator()<, void>() (this=<optimized out>) at /usr/include/c++/7/functional:551
 #5  std::_Function_handler<void (), std::_Bind<void (yb::tablet::Tablet::*(yb::tablet::Tablet*))()> >::_M_invoke(std::_Any_data const&) (__functor=...) at /usr/include/c++/7/bits/std_function.h:316
 #6  0x00007fd6a1d8c93c in std::function<void ()>::operator()() const (this=0x556c01ca80f0) at /usr/include/c++/7/bits/std_function.h:706
 #7  rocksdb::DBImpl::FilesChanged (this=this@entry=0x556c01ca7700) at ../../src/yb/rocksdb/db/db_impl.cc:4359
 #8  0x00007fd6a1db2b4f in rocksdb::DBImpl::BackgroundCallFlush (this=0x556c01ca7700, cfd=<optimized out>) at ../../src/yb/rocksdb/db/db_impl.cc:3285
 #9  0x00007fd6a1dcaa11 in rocksdb::DBImpl::FlushTask::DoRun (this=<optimized out>, suspender=<optimized out>) at ../../src/yb/rocksdb/db/db_impl.cc:346
 #10 0x00007fd6a1db8c04 in rocksdb::DBImpl::ThreadPoolTask::Run (this=0x556bfcd29d60, status=..., suspender=<optimized out>) at ../../src/yb/rocksdb/db/db_impl.cc:216
 #11 0x00007fd69d445d77 in yb::(anonymous namespace)::PriorityThreadPoolWorker::Run (this=0x556c01c05298) at ../../src/yb/util/priority_thread_pool.cc:188
 #12 0x00007fd69d444baa in std::__invoke_impl<void, void (yb::(anonymous namespace)::PriorityThreadPoolWorker::*&)(), yb::(anonymous namespace)::PriorityThreadPoolWorker*&> (__t=<optimized out>, __f=<optimized out>) at /usr/include/c++/7/bits/invoke.h:73
 #13 std::__invoke<void (yb::(anonymous namespace)::PriorityThreadPoolWorker::*&)(), yb::(anonymous namespace)::PriorityThreadPoolWorker*&> (__fn=<optimized out>) at /usr/include/c++/7/bits/invoke.h:95
 #14 std::_Bind<void (yb::(anonymous namespace)::PriorityThreadPoolWorker::*(yb::(anonymous namespace)::PriorityThreadPoolWorker*))()>::__call<void, 0> (__args=..., this=<optimized out>) at /usr/include/c++/7/functional:467
 #15 std::_Bind<void (yb::(anonymous namespace)::PriorityThreadPoolWorker::*(yb::(anonymous namespace)::PriorityThreadPoolWorker*))()>::operator()<> (this=<optimized out>) at /usr/include/c++/7/functional:551
 #16 std::__invoke_impl<void, std::_Bind<void (yb::(anonymous namespace)::PriorityThreadPoolWorker::*(yb::(anonymous namespace)::PriorityThreadPoolWorker*))()>&> (__f=...) at /usr/include/c++/7/bits/invoke.h:60
 #17 std::__invoke<std::_Bind<void (yb::(anonymous namespace)::PriorityThreadPoolWorker::*(yb::(anonymous namespace)::PriorityThreadPoolWorker*))()>&> (__fn=...) at /usr/include/c++/7/bits/invoke.h:95
 #18 std::_Bind<std::_Bind<void (yb::(anonymous namespace)::PriorityThreadPoolWorker::*(yb::(anonymous namespace)::PriorityThreadPoolWorker*))()>()>::__call<void> (__args=..., this=<optimized out>) at /usr/include/c++/7/functional:467
 #19 std::_Bind<std::_Bind<void (yb::(anonymous namespace)::PriorityThreadPoolWorker::*(yb::(anonymous namespace)::PriorityThreadPoolWorker*))()>()>::operator()<> (this=<optimized out>) at /usr/include/c++/7/functional:551
 #20 std::_Function_handler<void(), std::_Bind<std::_Bind<void (yb::(anonymous namespace)::PriorityThreadPoolWorker::*(yb::(anonymous namespace)::PriorityThreadPoolWorker*))()>()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /usr/include/c++/7/bits/std_function.h:316
 #21 0x00007fd69d4770ed in std::function<void ()>::operator()() const (this=0x556bfda36178) at /usr/include/c++/7/bits/std_function.h:706
 #22 yb::Thread::SuperviseThread (arg=0x556bfda36120) at ../../src/yb/util/thread.cc:739
 #23 0x00007fd6990086db in start_thread (arg=0x7fd66faa8700) at pthread_create.c:463
 #24 0x00007fd698d3188f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

@rajukumaryb
Copy link
Contributor

Stack when new test PgLibPqTest.ConcurrentInsertTruncateForeignKey is run for much longer -

Program terminated with signal 11, Segmentation fault.
#0  yb::tablet::Tablet::ShouldApplyWrite (this=0x2655620) at ../../../../../src/yb/tablet/tablet.cc:2374
2374      return !regular_db_->NeedsDelay();
#0  yb::tablet::Tablet::ShouldApplyWrite (this=0x2655620) at ../../../../../src/yb/tablet/tablet.cc:2374
#1  0x00007fb02371faf2 in yb::consensus::ReplicaState::ApplyPendingOperationsUnlocked (this=0x4b17a40, committed_op_id=..., could_stop=...) at ../../../../../src/yb/consensus/replica_state.cc:840
#2  0x00007fb02371f1b0 in yb::consensus::ReplicaState::AdvanceCommittedOpIdUnlocked (this=0x4b17a40, committed_op_id=..., could_stop=...) at ../../../../../src/yb/consensus/replica_state.cc:797
#3  0x00007fb0237072d7 in yb::consensus::RaftConsensus::EarlyCommitUnlocked (this=0x3e1a258, request=..., deduped_req=...) at ../../../../../src/yb/consensus/raft_consensus.cc:1684
#4  0x00007fb02370552f in yb::consensus::RaftConsensus::UpdateReplica (this=0x3e1a258, request=0x2a3ab58, response=<optimized out>) at ../../../../../src/yb/consensus/raft_consensus.cc:1632
#5  0x00007fb0237048b3 in yb::consensus::RaftConsensus::Update (this=<optimized out>, request=0x2a3ab58, response=<optimized out>, deadline=...) at ../../../../../src/yb/consensus/raft_consensus.cc:1204
#6  0x00007fb02449d13b in yb::tserver::ConsensusServiceImpl::UpdateConsensus (this=<optimized out>, req=0x2a3ab58, resp=0x3dbe558, context=...) at ../../../../../src/yb/tserver/tablet_service.cc:1665
#7  0x00007fb021d56481 in yb::consensus::ConsensusServiceIf::Handle (this=0x10fac00, call=...) at consensus.service.cc:100
#8  0x00007fb01de29f24 in yb::rpc::ServicePoolImpl::Handle (this=0x12d2fc0, incoming=...) at ../../../../../src/yb/rpc/service_pool.cc:262
#9  0x00007fb01ddcd617 in yb::rpc::InboundCall::InboundCallTask::Run (this=<optimized out>) at ../../../../../src/yb/rpc/inbound_call.cc:212
#10 0x00007fb01de35d30 in yb::rpc::(anonymous namespace)::Worker::Execute (this=0x2957340) at ../../../../../src/yb/rpc/thread_pool.cc:99
#11 0x00007fb01c2ca45a in yb::Thread::SuperviseThread (arg=<optimized out>) at ../../../../../src/yb/util/thread.cc:739
#12 0x00007fb016c6e694 in start_thread (arg=0x7fafe6d1b700) at pthread_create.c:333
#13 0x00007fb0169b041d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

@bmatican
Copy link
Contributor Author

Jotting down a recent ASAN failure from master highlighting use-after-free issue post shutdown: https://detective-gcp.dev.yugabyte.com/job/github-yugabyte-db-centos-master-clang-asan%2F626%2Fartifact%2Fbuild%2Fasan-clang-dynamic-ninja%2Fyb-test-logs%2Ftests-client__snapshot-txn-test%2FSnapshotTxnTest_MultiWriteWithRestart.log?max_lines=3000&start_line=9001

I'll change this issue description to repurpose it to be TRUNCATE specific and spin off a separate issue for the background flush in rocksdb not being waited on during destructor.

@rajukumaryb
Copy link
Contributor

rajukumaryb commented Jan 28, 2020

Stack from #3288 (comment) is the result of race between the following two accesses -

     @     0x7fcc56ba8159  yb::tablet::Tablet::ShouldApplyWrite() (src/yb/tablet/tablet.cc:2392)
     @     0x7fcc56bed205  yb::tablet::TabletPeer::ShouldApplyWrite() (src/yb/tablet/tablet_peer.cc:924)
     @     0x7fcc568e6146  yb::consensus::ReplicaState::ApplyPendingOperationsUnlocked(yb::OpId const&, yb::StronglyTypedBool<yb::consensus::CouldStop_Tag>) (src/yb/consensus/replica_state.cc:840)
     @     0x7fcc568e6c72  yb::consensus::ReplicaState::AdvanceCommittedOpIdUnlocked(yb::OpId const&, yb::StronglyTypedBool<yb::consensus::CouldStop_Tag>) (src/yb/consensus/replica_state.cc:797)
     @     0x7fcc568c6eb1  yb::consensus::RaftConsensus::EarlyCommitUnlocked(yb::consensus::ConsensusRequestPB const&, yb::consensus::RaftConsensus::LeaderRequest const&) (src/yb/consensus/raft_consensus.cc:1689)
     @     0x7fcc568cfe54  yb::consensus::RaftConsensus::UpdateReplica(yb::consensus::ConsensusRequestPB*, yb::consensus::ConsensusResponsePB*) (src/yb/consensus/raft_consensus.cc:1637)
     @     0x7fcc568d0e8f  yb::consensus::RaftConsensus::Update(yb::consensus::ConsensusRequestPB*, yb::consensus::ConsensusResponsePB*, std::chrono::time_point<yb::CoarseMonoClock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >) (src/yb/consensus/raft_consensus.cc:1209)
     @     0x7fcc5743baae  yb::tserver::ConsensusServiceImpl::UpdateConsensus(yb::consensus::ConsensusRequestPB const*, yb::consensus::ConsensusResponsePB*, yb::rpc::RpcContext) (src/yb/tserver/tablet_service.cc:1667)
     @     0x7fcc55157729  yb::consensus::ConsensusServiceIf::Handle(shared_ptr<yb::rpc::InboundCall>) (src/yb/consensus/consensus.service.cc:100)
     @     0x7fcc5158024b  yb::rpc::ServicePoolImpl::Handle(shared_ptr<yb::rpc::InboundCall>) (src/yb/rpc/service_pool.cc:262)
     @     0x7fcc51518d1f  yb::rpc::InboundCall::InboundCallTask::Run() (src/yb/rpc/inbound_call.cc:212)
     @     0x7fcc5158f6b6  Execute (src/yb/rpc/thread_pool.cc:99)
     @     0x7fcc5158bcc7  __invoke_impl<void, void (yb::rpc::(anonymous namespace)::Worker::*&)(), yb::rpc::(anonymous namespace)::Worker*&> (/usr/include/c++/7/bits/invoke.h:73)
     @     0x7fcc5158bcc7  __invoke<void (yb::rpc::(anonymous namespace)::Worker::*&)(), yb::rpc::(anonymous namespace)::Worker*&> (/usr/include/c++/7/bits/invoke.h:95)
     @     0x7fcc5158bcc7  __call<void, 0> (/usr/include/c++/7/functional:467)
     @     0x7fcc5158bcc7  operator()<> (/usr/include/c++/7/functional:551)
     @     0x7fcc5158bcc7  _M_invoke (/usr/include/c++/7/bits/std_function.h:316)
     @     0x7fcc4fc3567e  std::function<void ()>::operator()() const (/usr/include/c++/7/bits/std_function.h:706)
     @     0x7fcc4fc3567e  yb::Thread::SuperviseThread(void*) (src/yb/util/thread.cc:739)
     @     0x7fcc4a8dd6da
     @     0x7fcc4a60688e
     @ 0xffffffffffffffff
     @     0x7fcc56bb4a4d  yb::tablet::Tablet::Truncate(yb::tablet::TruncateOperationState*) (src/yb/tablet/tablet.cc:1779)
     @     0x7fcc56c36e5b  yb::tablet::TruncateOperation::DoReplicated(long, yb::Status*) (src/yb/tablet/operations/truncate_operation.cc:68)
     @     0x7fcc56c1f43f  yb::tablet::Operation::Replicated(long) (src/yb/tablet/operations/operation.cc:63)
     @     0x7fcc56c28600  yb::tablet::OperationDriver::ApplyTask(long, std::vector<yb::OpId, std::allocator<yb::OpId> >*) (src/yb/tablet/operations/operation_driver.cc:442)
     @     0x7fcc56c2a73e  yb::tablet::OperationDriver::ApplyOperation(long, std::vector<yb::OpId, std::allocator<yb::OpId> >*) (src/yb/tablet/operations/operation_driver.cc:421)
     @     0x7fcc56c2b41e  yb::tablet::OperationDriver::PrepareAndStart() (src/yb/tablet/operations/operation_driver.cc:287)
     @     0x7fcc56c2b8ad  yb::tablet::OperationDriver::PrepareAndStartTask() (src/yb/tablet/operations/operation_driver.cc:195)
     @     0x7fcc56c6112d  yb::tablet::PreparerImpl::ProcessItem(yb::tablet::OperationDriver*) (src/yb/tablet/preparer.cc:212)
     @     0x7fcc56c61231  yb::tablet::PreparerImpl::Run() (src/yb/tablet/preparer.cc:160)
     @     0x7fcc56c615c6  void std::__invoke_impl<void, void (yb::tablet::PreparerImpl::*&)(), yb::tablet::PreparerImpl*&>(std::__invoke_memfun_deref, void (yb::tablet::PreparerImpl::*&)(), yb::tablet::PreparerImpl*&) (/usr/include/c++/7/bits/invoke.h:73)
     @     0x7fcc56c615c6  std::__invoke_result<void (yb::tablet::PreparerImpl::*&)(), yb::tablet::PreparerImpl*&>::type std::__invoke<void (yb::tablet::PreparerImpl::*&)(), yb::tablet::PreparerImpl*&>(void (yb::tablet::PreparerImpl::*&)(), yb::tablet::PreparerImpl*&) (/usr/include/c++/7/bits/invoke.h:95)
     @     0x7fcc56c615c6  void std::_Bind<void (yb::tablet::PreparerImpl::*(yb::tablet::PreparerImpl*))()>::__call<void, , 0ul>(tuple<>&&, std::_Index_tuple<0ul>) (/usr/include/c++/7/functional:467)
     @     0x7fcc56c615c6  void std::_Bind<void (yb::tablet::PreparerImpl::*(yb::tablet::PreparerImpl*))()>::operator()<, void>() (/usr/include/c++/7/functional:551)
     @     0x7fcc56c615c6  std::_Function_handler<void (), std::_Bind<void (yb::tablet::PreparerImpl::*(yb::tablet::PreparerImpl*))()> >::_M_invoke(std::_Any_data const&) (/usr/include/c++/7/bits/std_function.h:316)
     @     0x7fcc558fa6ea  std::function<void ()>::operator()() const (/usr/include/c++/7/bits/std_function.h:706)
     @     0x7fcc558fa6ea  yb::FunctionRunnable::Run() (src/yb/util/threadpool.h:479)
     @     0x7fcc4fc3cdea  yb::ThreadPool::DispatchThread(bool) (src/yb/util/threadpool.cc:608)
     @     0x7fcc4fc400eb  void std::__invoke_impl<void, void (yb::ThreadPool::*&)(bool), yb::ThreadPool*&, bool&>(std::__invoke_memfun_deref, void (yb::ThreadPool::*&)(bool), yb::ThreadPool*&, bool&) (/usr/include/c++/7/bits/invoke.h:73)
     @     0x7fcc4fc400eb  std::__invoke_result<void (yb::ThreadPool::*&)(bool), yb::ThreadPool*&, bool&>::type std::__invoke<void (yb::ThreadPool::*&)(bool), yb::ThreadPool*&, bool&>(void (yb::ThreadPool::*&)(bool), yb::ThreadPool*&, bool&) (/usr/include/c++/7/bits/invoke.h:95)
     @     0x7fcc4fc400eb  void std::_Bind<void (yb::ThreadPool::*(yb::ThreadPool*, bool))(bool)>::__call<void, , 0ul, 1ul>(tuple<>&&, std::_Index_tuple<0ul, 1ul>) (/usr/include/c++/7/functional:467)
     @     0x7fcc4fc400eb  void std::_Bind<void (yb::ThreadPool::*(yb::ThreadPool*, bool))(bool)>::operator()<, void>() (/usr/include/c++/7/functional:551)
     @     0x7fcc4fc400eb  std::_Function_handler<void (), std::_Bind<void (yb::ThreadPool::*(yb::ThreadPool*, bool))(bool)> >::_M_invoke(std::_Any_data const&) (/usr/include/c++/7/bits/std_function.h:316)
     @     0x7fcc4fc3567e  std::function<void ()>::operator()() const (/usr/include/c++/7/bits/std_function.h:706)
     @     0x7fcc4fc3567e  yb::Thread::SuperviseThread(void*) (src/yb/util/thread.cc:739)
     @     0x7fcc4a8dd6da
     @     0x7fcc4a60688e
     @ 0xffffffffffffffff

@bmatican bmatican changed the title [docdb] Tablet shutdown race on CleanupIntentFiles [docdb] Various race conditions when doing concurrent TRUNCATE and write operations Jan 28, 2020
rajukumaryb added a commit that referenced this issue Feb 7, 2020
…condition between insert and truncate; disable rocksdb flush on truncate

Summary:
- Prevent rocksdb instance from calling `ListenFilesChanged` callback after being detached from `Tablet`

Full stack available at - #3288 (comment)

Follow Up Work: #3476

- Prevent race between `Tablet::AcquireLocksAndPerformDocOperations() -> Tablet::StartDocWriteOperation()` and `Tablet::Truncate()` by incrementing `pending_op_counter_`

Full stack available at -  #3288 (comment)

- Do not flush rocksdb memtable when user truncates table to prevent following crash on flush -

```
#0  0x000056371c706b00 in ?? ()
#1  0x00007f5229291099 in std::__invoke_impl<void, void (yb::tablet::Tablet::*&)(), yb::tablet::Tablet*&> (__t=<optimized out>, __f=<optimized out>) at /usr/include/c++/7/bits/invoke.h:73
#2  std::__invoke<void (yb::tablet::Tablet::*&)(), yb::tablet::Tablet*&> (__fn=<optimized out>) at /usr/include/c++/7/bits/invoke.h:95
#3  std::_Bind<void (yb::tablet::Tablet::*(yb::tablet::Tablet*))()>::__call<void, , 0ul>(std::tuple<>&&, std::_Index_tuple<0ul>) (__args=..., this=<optimized out>) at /usr/include/c++/7/functional:467
#4  std::_Bind<void (yb::tablet::Tablet::*(yb::tablet::Tablet*))()>::operator()<, void>() (this=<optimized out>) at /usr/include/c++/7/functional:551
#5  std::_Function_handler<void (), std::_Bind<void (yb::tablet::Tablet::*(yb::tablet::Tablet*))()> >::_M_invoke(std::_Any_data const&) (__functor=...) at /usr/include/c++/7/bits/std_function.h:316
#6  0x00007f5225aee92c in std::function<void ()>::operator()() const (this=0x56371c5534f0) at /usr/include/c++/7/bits/std_function.h:706
#7  rocksdb::DBImpl::FilesChanged (this=this@entry=0x56371c552b00) at ../../src/yb/rocksdb/db/db_impl.cc:4359
#8  0x00007f5225b14b1b in rocksdb::DBImpl::BackgroundCallFlush (this=this@entry=0x56371c552b00, cfd=cfd@entry=0x0) at ../../src/yb/rocksdb/db/db_impl.cc:3285
```

Full stack available at - #3288 (comment)

- WORKAROUND for race condition (#3288 (comment)) by using `ScopedPendingOperation` in `Tablet::ShouldApplyWrite()` to prevent it from seeing a null `regular_db_` due to a concurrent `Tablet::Truncate()`

Full stack available at - #3288 (comment)

Follow Up Work: #3477

Test Plan:
./yb_build.sh debug --cxx-test pg_libpq-test --gtest_filter PgLibPqTest.ConcurrentInsertTruncateForeignKey
./yb_build.sh debug --cxx-test snapshot-txn-test --gtest_filter SnapshotTxnTest.MultiWriteWithRestart

Reviewers: bogdan, sergei, mikhail

Reviewed By: mikhail

Subscribers: kannan, ybase

Differential Revision: https://phabricator.dev.yugabyte.com/D7808
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/docdb YugabyteDB core features kind/failing-test Tests and testing infra priority/high High Priority
Projects
None yet
Development

No branches or pull requests

2 participants