logstore: reschedule flush_if_necessary() on lost try_lock instead of dropping it - #914
Conversation
|
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## stable/v7.x #914 +/- ##
==============================================
Coverage ? 48.29%
==============================================
Files ? 110
Lines ? 13116
Branches ? 6326
==============================================
Hits ? 6334
Misses ? 2556
Partials ? 4226 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
|
thanks @shosseinimotlagh for this finding. well, I noticed that in UT we set flush_timer_frequency_us to 0, but I am not quite clear why. |
@JacksonYao287 test_log_store.cpp:172 — the test itself calls m_log_store->get_logdev()->flush_if_necessary(1) directly after every insert. That's not incidental; it's the mechanism. Since these logdevs have neither INLINE nor TIMER bits, the only thing driving flush attempts is this per-write explicit call — so many concurrent writes each fire their own flush_if_necessary() concurrently, and whichever one loses the try_lock race on the batch's last write has nothing left to retry it. That's exactly the reproducer, and it's not a test artifact — it's a faithful simulation of a legitimate production pattern: a caller who deliberately chose flush_mode_t::EXPLICIT to self-drive flushing without paying for a background timer. That's the key point for the fix's justification: "the timer should always be on" doesn't actually close this gap in general, because EXPLICIT-only logdevs (a deliberate, supported mode for callers who want to control flush timing themselves) never get a timer safety net in the first place — timer-based mitigation is orthogonal to this bug. |
JacksonYao287
left a comment
JacksonYao287
left a comment
There was a problem hiding this comment.
thanks , mehdi, the explanation makes sense to me. I have another concern, pls take a look
| auto const pending_sz = m_pending_flush_size.load(std::memory_order_relaxed); | ||
| bool const flush_by_size = (pending_sz >= threshold_size); |
There was a problem hiding this comment.
if we schedule the flush to the flush_thread, when it is executed, flush_by_size and flush_by_time are both false, we will still lose this flush right?
so for the case mentioned in this PR, do we need a way to guarantee the flush will be done?
There was a problem hiding this comment.
You're right, and this needed a real fix.
The reschedule as originally written re-invokes flush_if_necessary(), which re-derives flush_by_size/flush_by_time from scratch. flush() resets m_last_flush_time unconditionally at its very start, so the concurrent flush that won the race can reset that clock right before the retry runs — if this write's own size never crosses threshold_size on its own, both conditions can read false and the retry silently drops, exactly the failure this PR set out to fix.
Fix: flush_if_necessary() now takes a force parameter. The reschedule passes force=true, which skips the size/time re-derivation entirely and goes straight to try_lock. We already decided this data needs flushing when we entered this branch — the retry's only job is to keep trying to acquire the lock, not re-litigate whether to. Still a non-blocking try_to_lock, so no new deadlock surface.
Building a deterministic repro to verify this (rather than relying on timing/luck) surfaced a second, separate, more severe issue in the original reschedule — present with or without force, so it's independent of that fix and in fact predates this PR entirely (it's already in the original reschedule-on-lost-race commit): IOReactor::deliver_msg takes a same-thread shortcut, calling the target inline instead of queuing it whenever sender and receiver are the same reactor. The reschedule always targets flush_thread(), and we're always already on flush_thread() by the time we reach it, so every failed retry was a real recursive call on the same stack, not a queued task. Under sustained lock contention (confirmed with the lock held for ~200ms in testing) that recursion runs tens of thousands of frames deep and stack-overflows the process. Fixed by routing the retry through iomgr::reactor_regex::random_worker first (the same pattern already used a few lines below in this file), forcing a genuine cross-thread hop so the stack always unwinds between attempts.
Added LogStoreTest.FlushIfNecessaryRetrySurvivesStaleClockReset to cover both, deterministically (two small _PRERELEASE-only LogDev hooks instead of a real racer flush(), which can't cleanly isolate this — releasing it would flush the target write regardless of the fix). Verified all four combinations, same test unchanged: neither fix → crash (5/5), force alone → crash (5/5), random_worker alone → fails (9/10), both → passes (20/20). Pushed.
… dropping it Root cause ---------- LogDev::flush_if_necessary() uses std::try_to_lock on m_flush_mtx. If it loses that race to a concurrent flush() (another write's own flush_if_necessary() call, or HomeLogStore::truncate()'s internal flush()), it silently gives up -- no retry, no rescheduling. The concurrent flush's own snapshot of m_log_idx may not include the data that made *this* call decide to flush, so the dropped attempt can leave that data unflushed indefinitely, with nothing to notice. In production this is normally masked by the periodic flush timer (flush_timer_frequency_us) eventually retrying. But test_log_store.cpp disables that timer globally for the whole binary (flush_timer_frequency_us=0, comment: "Currently only tests set it to 0"), so flush_if_necessary()'s own try_lock is the *only* path that will ever flush pending data in these tests. LogStoreTest.VarRateInsertThenTruncate's Step 4 deliberately runs writes and repeated truncate_validate() calls concurrently; if the very last batch issued in a run has its own flush_if_necessary() call lose the try_lock race -- because a concurrent truncate()'s internal flush() is holding the mutex at that exact instant -- and nothing else ever calls flush_if_necessary() again for that logdev, that batch's data is never flushed, and any waiter on its completion (LogStoreTest::wait_for_inserts()) blocks forever. How this was diagnosed ----------------------- - Reproduced by looping test_log_store --gtest_filter= LogStoreTest.VarRateInsertThenTruncate:LogStoreTest.ThrottleSeqInsertThenRecover repeatedly; the hang appeared within 2-12 attempts, consistently. - gdb (thread apply all bt, all threads) on a stuck process showed only the main thread blocked in wait_for_inserts()'s condition_variable::wait -- every other thread (including the dedicated log_flush_thread) fully idle in epoll_wait. Nothing deadlocked; the process genuinely had nothing left to do. - Temporary diagnostic logging (issue/complete per LSN) showed exactly one clean insert_next_batch()-sized batch (10 consecutive lsns, one store) issued but never completed, with zero flush or I/O errors logged anywhere in the run. - Confirmed pre-existing and unrelated to any other in-flight change: an unmodified stable/v7.x checkout reproduced the identical signature (same "one store's last batch never completes, no errors, nothing deadlocked") under the same repro loop. - Confirmed the mechanism directly: added temporary logging inside flush_if_necessary() itself (try_lock=SUCCESS/FAILED/threshold_not_met per call) and observed no further flush attempt at all for the affected logdev after the stuck batch's own issuing thread finished (consistent with that thread's own flush_if_necessary() call losing the race and nothing else ever coming along to retry). Fix --- When the try_lock fails, reschedule a follow-up flush_if_necessary() attempt onto the log store flush thread via iomanager.run_on_forget(), mirroring the existing reschedule already used a few lines above for the !can_flush_in_this_thread() case. This does not change behavior during shutdown: LogDev::stop() already performs its own guaranteed, blocking flush_under_guard() call (a real blocking lock acquire, not try_to_lock) before teardown, which flushes everything up to m_log_idx - 1 regardless of whether a rescheduled flush_if_necessary() attempt bails out early via is_stopping(). Verification ------------ Stress-tested by looping the same two-test gtest filter 60 consecutive times after the fix: 0 hangs out of 60 attempts (previously reproduced within 2-12 attempts on the same machine/build, both with and without this fix absent).
…eck, and fix a latent stack overflow in it A reviewer (JacksonYao287) flagged that the reschedule added in the previous commit re-invokes flush_if_necessary(), which re-derives flush_by_size/ flush_by_time from scratch. LogDev::flush() unconditionally resets m_last_flush_time at its very start, so the concurrent flush that stole the race will, by the time the retry runs, likely have already reset that clock to "now" (flush_by_time re-evaluates false) while this call's own pending size may still be under threshold_size (flush_by_size false too) -- silently dropping the retry with nothing left to trigger it again. Verified with a deterministic repro (a temporary gate hook holding the flush lock for a controlled window) before and after: reliably reproduces the drop pre-fix, passes reliably post-fix. Fix: flush_if_necessary() gains a `force` parameter. The reschedule now passes force=true, which skips the size/time re-derivation entirely and goes straight to try_lock -- the retry's only job is to keep trying to actually acquire the lock, not re-litigate whether to. Still a non-blocking try_to_lock, so no new deadlock surface. Building that same repro also surfaced a separate, more severe, pre-existing bug in the original reschedule: IOReactor::deliver_msg takes a same-thread shortcut, calling the target handler inline instead of queuing it whenever sender and receiver are the same reactor. The reschedule always targets flush_thread(), and by construction we're always already on flush_thread() when we reach it (that's how we got past can_flush_in_this_thread()), so every failed retry was a real recursive call on the same stack, not a queued task. Under sustained lock contention (confirmed with a lock held for as little as ~200ms) that recursion runs tens of thousands of frames deep and stack-overflows the process -- reproduced identically with and without the force=true change above, confirming it predates this PR entirely. Fixed by bouncing the retry through iomgr::reactor_regex:: random_worker first (the same pattern already used a few lines below in this file for an analogous reentrancy concern), forcing a genuine cross-thread hop so the message is always queued and this stack frame unwinds before the retry runs, no matter how many times it fails.
Adds LogStoreTest.FlushIfNecessaryRetrySurvivesStaleClockReset, a deterministic repro for the gap fixed in the previous commit (flush_if_necessary()'s lost-try_lock-race reschedule silently dropped by a stale m_last_flush_time reset) and for the stack overflow that turned out to predate it. A real racer flush() call can't cleanly isolate this: whatever holds the lock long enough for the target write's try_lock to fail will, once released, take its own fresh snapshot of m_log_idx -- which by then includes the target write too, so releasing the racer would flush it regardless of whether the fix is present. Instead this adds two small, _PRERELEASE-only LogDev hooks: - test_acquire_flush_mtx(): grabs the real m_flush_mtx directly, without going through flush() at all, so releasing it later never triggers a snapshot/flush of its own. - test_touch_last_flush_time(): resets m_last_flush_time on demand (gated by the "test_touch_last_flush_time" FLIP), simulating the side effect of a concurrent flush completing without the side effect of actually flushing anything. Verified against all three relevant code states, same test unchanged: - force removed (random_worker kept): fails (assertion -- write never completes), 9/10 runs. - random_worker reverted to flush_thread() (force kept): crashes (SIGSEGV, the stack overflow from the previous commit), 5/5 runs. - both fixes present: passes, 20/20 runs.
…test No functional change -- trims the explanatory comments added in the previous two commits (force flag, random_worker routing, and the new UT's docstring) down to the essential why, without dropping any of the reasoning.
c758991 to
f9bbf11
Compare
"held for just ~200ms" implied a verified lower bound; only 200ms was actually tested, not shorter durations. Reword to state what was actually confirmed.
|
|
||
| bool LogDev::flush_if_necessary(int64_t threshold_size) { | ||
| bool LogDev::flush_if_necessary(int64_t threshold_size, bool force) { | ||
| if (is_stopping()) return false; |
There was a problem hiding this comment.
generally ，LGTM。a small concern is that if is_stopping here returns false, then even if force is true, we will still lose that flush?
There was a problem hiding this comment.
@JacksonYao287 force fixes the steady-state hang (no periodic timer to retry); shutdown durability is a separate, already-correct guarantee (append_async's own is_stopping() gate + stop()'s blocking flush_under_guard()), and the two don't need to cooperate for correctness — force racing against is_stopping() was never load-bearing.
You're right that is_stopping() short-circuits before force is even checked — so a retry that lands after is_stopping() flips is dropped regardless of force. That's not new to this change though (every method here gates on is_stopping() first), and it's harmless in practice: LogDev::stop() has its own independent safety net for exactly this window — after draining pending_request_num it calls flush_under_guard(), which takes a plain blocking lock (not try_lock), so it can't lose a race. Any write that reached flush_if_necessary() already holds a pending_request_num slot until that call returns, so its data is already in the pending buffer by the time stop()'s drain completes — flush_under_guard()'s own flush picks it up regardless of what happened to that write's retry chain. force is specifically about the steady-state hang (no periodic timer to retry later); shutdown durability comes from stop()'s blocking flush, which doesn't depend on this retry at all.
3 participants
Scenario
LogDev::flush_if_necessary()decides whether pending data needs flushing, then tries to grab the flush mutex withstd::try_to_lock:If the
try_lockloses the race — because some other flush is holding the mutex right at that instant (another write's ownflush_if_necessary()call, orHomeLogStore::truncate()'s internalflush()) — this call just gives up. No retry, no rescheduling. That's fine as long as something else is guaranteed to callflush_if_necessary()again later for the same logdev — normally the periodic flush timer (flush_timer_frequency_us) fills that role.The gap: if the periodic timer is disabled (
flush_timer_frequency_us = 0) and this happens to be the last write issued for that logdev in a given run, nothing ever callsflush_if_necessary()again. The data behind that lost race sits unflushed indefinitely, and anything waiting on its completion callback blocks forever.Concretely, this reproduces in
LogStoreTest.VarRateInsertThenTruncate(test_log_store.cpp), which disables the timer globally for the whole binary and deliberately runs writes concurrently with repeatedtruncate_validate()calls in its Step 4 — exactly the write-vs-truncate mutex race described above, on the very last batch issued.Fix v1
When the
try_lockfails, reschedule a follow-upflush_if_necessary()attempt viaiomanager.run_on_forget(), mirroring the existing reschedule already used a few lines above for the!can_flush_in_this_thread()case. The concurrent flush holding the mutex will release it shortly, so the rescheduled attempt gets a real chance to succeed instead of the data being silently abandoned.Follow-up 1: the reschedule can still be silently dropped by a stale clock
Review caught that the reschedule just re-invokes
flush_if_necessary(), which re-derivesflush_by_size/flush_by_timefrom scratch.LogDev::flush()unconditionally resetsm_last_flush_timeat its very start, so the concurrent flush that just won the race may have already reset that clock by the time the retry runs —flush_by_timecan read false again, and if this write's own size never crossesthreshold_sizeon its own,flush_by_sizestays false too, silently dropping the retry with nothing left to trigger it again.Fix:
flush_if_necessary()gains aforceparameter. The reschedule now passesforce=true, which skips the size/time re-derivation entirely and goes straight totry_lock— we already decided this data needs flushing, so the retry's only job is to keep trying to acquire the lock, not re-litigate whether to. Still a non-blockingtry_to_lock, so no new deadlock surface.Follow-up 2: the reschedule itself could stack-overflow the process
Building a deterministic repro for follow-up 1 surfaced a separate, more severe, pre-existing bug in the original reschedule (present with or without
force, i.e. it predates this PR's own fix):IOReactor::deliver_msgtakes a same-thread shortcut, calling the target handler inline instead of queuing it whenever sender and receiver are the same reactor. The reschedule always targetsflush_thread(), and by construction we're always already onflush_thread()when we reach it (that's how we got pastcan_flush_in_this_thread()), so every failed retry was a real recursive call on the same stack, not a queued task. Under sustained lock contention (confirmed with the lock held for ~200ms in testing) that recursion runs tens of thousands of frames deep and stack-overflows the process.Fix: route the retry through
iomgr::reactor_regex::random_workerfirst (the same pattern already used a few lines below in this file for an analogous reentrancy concern) instead offlush_thread()directly. This forces a genuine cross-thread hop — the message is queued and the stack unwinds before the retry runs, no matter how many timestry_lockfails.Regression test
LogStoreTest.FlushIfNecessaryRetrySurvivesStaleClockResetdeterministically reproduces both follow-up issues using two small_PRERELEASE-onlyLogDevtest hooks (test_acquire_flush_mtx(),test_touch_last_flush_time()) instead of a real racerflush()call, which can't cleanly isolate the bug (releasing it would always flush the target write anyway, masking the result regardless of the fix). Verified against all four combinations of the two fixes, same test unchanged:forcerandom_workerWhy this doesn't reintroduce anything during shutdown
If the rescheduled attempt runs after
is_stopping()has become true, it just returns immediately — same as today, no new reschedule. That's fine because shutdown already has its own independent, guaranteed flush:LogDev::stop()callsflush_under_guard(), which takesflush_guard()with a real blockingunique_lock(nottry_to_lock) and then callsflush()unconditionally. That flush covers everything up tom_log_idx - 1, andm_log_idxis already incremented synchronously at append time — well before any later, asynchronousflush_if_necessary()attempt — so any data a dropped reschedule would have covered is still guaranteed to be flushed bystop()'s own path before teardown proceeds. The reschedule and the shutdown-guaranteed flush are two independent safety nets for two different situations (normal operation vs. shutdown), not two paths racing over the same data.