Only flush after recovery for retryable IOError

[cbi42]

#11872 causes a unit test to start failing with the error message below. The cause is that the additional call to FlushAllColumnFamilies() in DBImpl::ResumeImpl() can run while DB is closing. More detailed explanation: there are two places where we call ResumeImpl():

1. in ErrorHandler::RecoverFromBGError, for manual resume or recovery from errors like OutOfSpace through sst file manager, and
2. in Errorhandler::RecoverFromRetryableBGIOError, for error recovery from errors like flush failure due to retryable IOError. This is tracked by ErrorHandler::recovery_thread_.

Here is how DB close waits for error recovery:

rocksdb/db/db_impl/db_impl.cc

Lines 540 to 543 in 49da91e

	error_handler_.CancelErrorRecovery();
	while (error_handler_.IsRecoveryInProgress()) {
	bg_cv_.Wait();
	}

CancelErrorRecovery() waits until recovery_thread_ finishes and IsRecoveryInProgress() checks the recovery_in_prog_ flag. The additional call to FlushAllColumnFamilies() in ResumeImpl() happens after it clears bg error and the recovery_in_prog_ flag:

rocksdb/db/db_impl/db_impl.cc

Lines 436 to 463 in 49da91e

	s = error_handler_.ClearBGError();
	} else {
	// NOTE: this is needed to pass ASSERT_STATUS_CHECKED
	// in the DBSSTTest.DBWithMaxSpaceAllowedRandomized test.
	// See https://github.com/facebook/rocksdb/pull/7715#issuecomment-754947952
	error_handler_.GetRecoveryError().PermitUncheckedError();
	}
	if (s.ok()) {
	ROCKS_LOG_INFO(immutable_db_options_.info_log, "Successfully resumed DB");
	} else {
	ROCKS_LOG_INFO(immutable_db_options_.info_log, "Failed to resume DB [%s]",
	s.ToString().c_str());
	}
	// Check for shutdown again before scheduling further compactions,
	// since we released and re-acquired the lock above
	if (shutdown_initiated_) {
	s = Status::ShutdownInProgress();
	}
	if (s.ok()) {
	// Since we drop all non-recovery flush requests during recovery,
	// and new memtable may fill up during recovery,
	// schedule one more round of flush.
	FlushOptions flush_opts;
	flush_opts.allow_write_stall = false;
	flush_opts.wait = false;
	Status status = FlushAllColumnFamilies(

. So if ResumeImpl() is called in RecoverFromBGError(), we can have a thread running FlushAllColumnFamilies() while DB is closing and thought that recovery is done.

The fix is to only do the additional call to FlushAllColumnFamilies() when doing error recovery through Errorhandler::RecoverFromRetryableBGIOError by setting flags in DBRecoverContext.

Test plan: gtest-parallel --repeat=100 --workers=4 ./error_handler_fs_test --gtest_filter="*AutoRecoverFlushError*" reproduces the error pretty reliably.

[----------] Global test environment set-up.
[----------] 1 test from DBErrorHandlingFSTest
[ RUN      ] DBErrorHandlingFSTest.AutoRecoverFlushError
error_handler_fs_test: db/column_family.cc:1618: rocksdb::ColumnFamilySet::~ColumnFamilySet(): Assertion `last_ref' failed.
Received signal 6 (Aborted)
...
#10 0x00007fac4409efd6 in __GI___assert_fail (assertion=0x7fac452c0afa "last_ref", file=0x7fac452c9fb5 "db/column_family.cc", line=1618, function=0x7fac452cb950 "rocksdb::ColumnFamilySet::~ColumnFamilySet()") at assert.c:101
101     in assert.c
#11 0x00007fac44b5324f in rocksdb::ColumnFamilySet::~ColumnFamilySet (this=0x7b5400000000) at db/column_family.cc:1618
1618        assert(last_ref);
#12 0x00007fac44e0f047 in std::default_delete<rocksdb::ColumnFamilySet>::operator() (this=0x7b5800000940, __ptr=0x7b5400000000) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/unique_ptr.h:85
85              delete __ptr;
#13 std::__uniq_ptr_impl<rocksdb::ColumnFamilySet, std::default_delete<rocksdb::ColumnFamilySet> >::reset (this=0x7b5800000940, __p=0x0) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/unique_ptr.h:182
182               _M_deleter()(__old_p);
#14 std::unique_ptr<rocksdb::ColumnFamilySet, std::default_delete<rocksdb::ColumnFamilySet> >::reset (this=0x7b5800000940, __p=0x0) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/unique_ptr.h:456
456             _M_t.reset(std::move(__p));
#15 rocksdb::VersionSet::~VersionSet (this=this@entry=0x7b5800000900) at db/version_set.cc:5081
5081      column_family_set_.reset();
#16 0x00007fac44e0f97a in rocksdb::VersionSet::~VersionSet (this=0x7b5800000900) at db/version_set.cc:5078
5078    VersionSet::~VersionSet() {
#17 0x00007fac44bf0b2f in std::default_delete<rocksdb::VersionSet>::operator() (this=0x7b8c00000068, __ptr=0x7b5800000900) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/unique_ptr.h:85
85              delete __ptr;
#18 std::__uniq_ptr_impl<rocksdb::VersionSet, std::default_delete<rocksdb::VersionSet> >::reset (this=0x7b8c00000068, __p=0x0) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/unique_ptr.h:182
182               _M_deleter()(__old_p);
#19 std::unique_ptr<rocksdb::VersionSet, std::default_delete<rocksdb::VersionSet> >::reset (this=0x7b8c00000068, __p=0x0) at /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/unique_ptr.h:456
456             _M_t.reset(std::move(__p));
#20 rocksdb::DBImpl::CloseHelper (this=this@entry=0x7b8c00000000) at db/db_impl/db_impl.cc:676
676       versions_.reset();
#21 0x00007fac44bf1346 in rocksdb::DBImpl::CloseImpl (this=0x7b8c00000000) at db/db_impl/db_impl.cc:720
720     Status DBImpl::CloseImpl() { return CloseHelper(); }
#22 rocksdb::DBImpl::~DBImpl (this=this@entry=0x7b8c00000000) at db/db_impl/db_impl.cc:738
738       closing_status_ = CloseImpl();
#23 0x00007fac44bf2bba in rocksdb::DBImpl::~DBImpl (this=0x7b8c00000000) at db/db_impl/db_impl.cc:722
722     DBImpl::~DBImpl() {
#24 0x00007fac455444d4 in rocksdb::DBTestBase::Close (this=this@entry=0x7b6c00000000) at db/db_test_util.cc:678
678       delete db_;
#25 0x00007fac455455fb in rocksdb::DBTestBase::TryReopen (this=this@entry=0x7b6c00000000, options=...) at db/db_test_util.cc:707
707       Close();
#26 0x00007fac45543459 in rocksdb::DBTestBase::Reopen (this=0x7ffed74b79a0, options=...) at db/db_test_util.cc:670
670       ASSERT_OK(TryReopen(options));
#27 0x00000000004f2522 in rocksdb::DBErrorHandlingFSTest_AutoRecoverFlushError_Test::TestBody (this=this@entry=0x7b6c00000000) at db/error_handler_fs_test.cc:1224
1224      Reopen(options);

[facebook-github-bot]

@cbi42 has imported this pull request. If you are a Meta employee, you can view this diff on Phabricator.

[jowlyzhang]

LGTM, thanks for the fix.

[jaykorean]

} else if (context.flush_after_recovery) {

would do the same without re-checking s.ok() below, but not a big deal.

[cbi42]

Do you mean scheduling compaction in the else if block? We need to do that when context.flush_after_recovery is false too.

[jaykorean]

Ahh never mind. I missed the collapsed part of the code. I didn't see we were calling FlushAll() above between line 460 - 471

I originally meant line 456 would stay as if (s.ok()), but then you will trigger FlushAll() when flush_after_recovery is false.

You can disregard my comment above

[facebook-github-bot]

@cbi42 merged this pull request in 1c871a4.

[anand1976]

Can this scenario be avoided if we check shutdown_initiated_ here?

[cbi42]

I think it would be the same as the existing check in line 453 (in the same critical section). I don't think it would work since db mutex is released/re-acquired several times in FlushAllColumnFamilies().

[anand1976]

Ok, that's true. Its dropping the locking before scheduling the flush.