Issue 4900: Read an unflushed ledger LAC from the memtable

[kalayciburak]

Descriptions of the changes in this PR:

Fix #4900

Motivation

SortedLedgerStorage.getLastAddConfirmed must not return an older persisted LAC when a newer entry is still in the memtable. FileInfo eviction can leave the index with an older LAC or without the newer entry offsets, even though the entry remains readable from the memtable.

Changes

• Check the cached LAC first so the common path keeps the same cost as before.
• Check the memtable after a cache miss and return its newer LAC when one is available.
• Write that newer value back to LedgerCache so later reads and LAC watchers do not observe a value moving backwards.
• Recheck the memtable when the underlying index lookup misses.

Tests

• mvn -B -pl bookkeeper-server -Dtest=SortedLedgerStorageTest -Dsurefire.failIfNoSpecifiedTests=false test (12 tests, 0 failures)
• mvn -B -pl bookkeeper-server checkstyle:check (0 violations)

The regression test flushes entries through LAC 3, adds entries through LAC 8, evicts the ledger's FileInfo caches, and verifies LAC 8 before and after flushing the remaining memtable entries.

[djsweet]

I have an alternative PR, #4902, that we've been using in production as a workaround for this bug.

It's worth pointing out that both of these PRs require a fix for #4895 to function correctly when ledger metadata is in use.

[djsweet]

Thinking a bit more on this, I'm not sure this is a fully correct fix. Consider the scenario posed by #4900, but where the first ledger already exists, and is committed into InterleavedLedgerStorage.

If you write to over 20,000 ledgers with small payloads below the skipListSizeLimit, then the call to interleavedLedgerStorage.getLastAddConfirmed will not be able to access the LAC from the Ledger Cache, but instead will read from the committed value in InterleavedLedgerStorage, which will be behind the LAC in the memTable. This means the LAC gets reset backwards, spuriously.

#4902 always reads from the entryMemTable before interleavedLedgerStorage, so it shouldn't be susceptible to the same problem.

[kalayciburak]

Thanks djsweet, fixed this in c46faa0. getLastAddConfirmed now checks the memtable before the index and keeps the higher LAC, while preserving the retry when the index misses during a flush. Added regression coverage for the existing-ledger case and the retry path.

[codelipenghui]

Thanks for the fix and the quick follow-up. I reproduced #4900 on master and checked that this PR fixes it:

• master: an end-to-end V3 read fails with BKNoSuchEntryException. The setup was one bookie with SortedLedgerStorage and openFileLimit=2, 12 ledgers, memtable not yet flushed, reading the first ledger. testGetLastAddConfirmedAfterFileInfoEviction fails with NoEntryException: Entry 0 not found in 0.
• this PR (c46faa0): both pass. The related suites I ran also pass (116 tests), and checkstyle is clean. Those suites were SortedLedgerStorage*, LedgerStorageCheckpointTest, LedgerCacheTest, EntryMemTableTest, BookieReadWriteTest, TestReadEntryListener, LedgerRecoveryTest, TestReadLastConfirmedLongPoll, TestReadLastConfirmedAndEntry, ReadLastConfirmedOpTest and ExplicitLacTest.

Requesting changes for two things:

1. The partially flushed case from @djsweet's comment only stays fixed until the memtable is flushed. The index-derived LAC is still cached in the FileInfo. Once the rest of the ledger is flushed, the bookie reports the old LAC again (8 → 3 in a repro). Details and a fix are inline. Writing the memtable value back to the ledger cache also lets long-poll reads (waitForLastAddConfirmedUpdate) see it.
2. Tests: the new mock-based tests can't see that caching side effect. Also, the original test's flush() doesn't flush, because its checkpoint source returns Checkpoint.MAX. A real-storage test would cover it: flush part of a ledger, evict its FileInfo, then check the LAC before and after flushing the rest.

Also suggested, not blocking: check the cached LAC before the memtable. That avoids a memtable lookup on every V3 read and makes the write-back natural (see inline). The PR description still describes the first version ("on those misses", 6 tests, ENOLEDGER), so it's worth updating to match the final approach.

[codelipenghui]

The returned value is now correct while the newer entries are still in the memtable. But interleavedLedgerStorage.getLastAddConfirmed() still caches the index-derived LAC in the reloaded FileInfo (InterleavedLedgerStorage#getLastAddConfirmed calls ledgerCache.updateLastAddConfirmed). Nothing writes the memtable value back.

Repro, using a real SortedLedgerStorage with CheckpointSource.DEFAULT so flush() really flushes:

1. Add entries 0–4 (LAC = entryId − 1) and flush. Add entries 5–9. Evict ledger 0's FileInfo.
2. getLastAddConfirmed(0) returns 8, which is correct. But the ledger cache now holds 3.
3. Call flush() while the FileInfo is still cached. getLastAddConfirmed(0) now returns 3.

So once the rest of the ledger is flushed, the LAC still goes backwards (8 → 3), which is the case @djsweet described. It stays at 3 until a newer LAC arrives or the FileInfo is evicted again.

Writing the winning value back fixes it. FileInfo#setLastAddConfirmed only moves forward and also notifies long-poll watchers:

if (memTableLac == null || memTableLac <= persistedLac) {
    return persistedLac;
}
return interleavedLedgerStorage.ledgerCache.updateLastAddConfirmed(ledgerId, memTableLac);

The catch branch needs the same write-back for latestMemTableLac, ignoring NoLedgerException. With that, the repro returns 8 both before and after the flush. Alternatively, check the cached LAC first (see the next comment).

[codelipenghui]

This puts a memtable lookup in front of every call: a read lock, up to two skip-list floorKey calls, and a get-entry stats event in EntryMemTable#getLastEntry. That includes the common case where the FileInfo already has the LAC cached, and ReadEntryProcessorV3 calls this on every V3 entry read.

I ran a quick local loop: 1000 ledgers × 200 unflushed entries, LAC cached.

• Single thread: about 38 ns per call on master, about 160 ns with this change.
• 8 threads: about 8.5 M calls/s on master, about 3.9 M with this change.

Every LAC read also counts as a memtable get in the skip-list stats.

Checking the cache first keeps the common path the same as master and only touches the memtable after an eviction. This is essentially the order #4902 uses:

LedgerCache ledgerCache = interleavedLedgerStorage.ledgerCache;
Long lac = null;
try {
    lac = ledgerCache.getLastAddConfirmed(ledgerId);
} catch (Bookie.NoLedgerException nle) {
    // no FileInfo/index; the memtable may still have the ledger
}
if (lac != null) {
    return lac;
}
Long memLac = lastAddConfirmedFromMemTable(ledgerId);
if (memLac != null) {
    try {
        return ledgerCache.updateLastAddConfirmed(ledgerId, memLac);
    } catch (Bookie.NoLedgerException nle) {
        return memLac;
    }
}
// nothing unflushed (or it was just flushed): the index is complete
return interleavedLedgerStorage.getLastAddConfirmed(ledgerId);

This is safe against a concurrent flush. flushSnapshot writes every snapshot entry to the index before clearSnapshot, and getLastEntry still sees the snapshot until then. So if the memtable has nothing, the index already has everything, and the retry is no longer needed.

Locally this passes the eviction test, the partially flushed repro above and an end-to-end V3 read, at the same per-call cost as master.

[codelipenghui]

Mocking InterleavedLedgerStorage hides the side effect behind the remaining bug. The real getLastAddConfirmed() also stores the index-derived LAC in the FileInfo cache, and that is what later comes back as the stale value. So this test passes while a real storage still goes 8 → 3 (see the comment on SortedLedgerStorage). Both mock tests would also need rework with either fix, because a mock's ledgerCache field is null.

Could this be a real-storage test instead? Roughly:

1. Use CheckpointSource.DEFAULT so flush() really flushes.
2. Add entries 0–4 and flush, then add 5–9.
3. Evict ledger 0's FileInfo, either with openFileLimit pressure as in the test above or by invalidating both IndexPersistenceMgr caches from the test package.
4. Assert 8, call flush(), and assert 8 again.

The last assertion fails on the current head.

[codelipenghui]

This flush() doesn't flush the memtable. In this class, checkpointSource.newCheckpoint() returns Checkpoint.MAX. EntryMemTable#snapshot(Checkpoint.MAX) only takes a snapshot when kvmap.cp.compareTo(MAX) < 0, which is never true for MAX.

I checked that entry 0 is still in storage.memTable afterwards. So the next assertion runs the memtable path again, not the post-flush index path.

Using CheckpointSource.DEFAULT (which returns Checkpoint.MIN) for this storage, and asserting storage.memTable.isEmpty() after the flush, would make it test what the message says. The current code does return the right LAC from the index after a real flush.

[codelipenghui]

Nit: the index file does exist after eviction. FileInfoBackingCache#releaseFileInfo calls FileInfo.close(true), which creates a header-only .idx (1024 bytes). What's missing are the index entries. That's why the lookup throws NoEntryException, and why master returns ENOENTRY here rather than ENOLEDGER.

[codelipenghui]

Nit: assertThrows(IOException.class, () -> storage.getLastAddConfirmed(9_999L)) reads better than assertTrue(msg, false).

Also, entry 0 can't carry LAC 3 (lac = 3L above), because a piggybacked LAC is always lower than the entry id. Writing a few entries with LAC = entryId - 1 would keep the test realistic.

[codelipenghui]

Thanks for the update. Writing the memtable LAC back to the ledger cache fixes the case from my earlier review. In my repro the LAC now stays at 8 after the rest of the ledger is flushed (it used to go back to 3), and a long poll after a LAC read no longer waits. The new real-storage test guards this, and the other test points and nits are addressed too.

Checked on 7815444:

• SortedLedgerStorageTest (8 tests), the same 12 related suites as before (114 tests) and checkstyle all pass.
• An end-to-end V3 read of an evicted, unflushed ledger succeeds.

Two inline comments. The main one: the PR's tests no longer cover #4900 itself, i.e. an evicted ledger with nothing flushed. The cache-first suggestion from my earlier comment on line 243 still applies, but it's optional.

[codelipenghui]

Since entries 0–4 are flushed here, the index lookup in getLastAddConfirmed succeeds (it returns 3), so this test only runs the try branch. The catch branch is the fix for #4900 itself: the index throws for an evicted ledger with nothing flushed. That branch isn't covered any more. The earlier version of this test was replaced, and testGetLastAddConfirmedRetriesAfterIndexMiss only reaches that branch with an empty memtable.

I checked locally with two changes to SortedLedgerStorage#getLastAddConfirmed. All 8 tests in this class still pass with either one:

• The catch branch replaced by a plain index retry. This brings Reads in SortedLedgerStorage erroneously report ENOLEDGER for more unflushed ledgers in the memtable than openFileLimit #4900 back: an end-to-end V3 read of an evicted, unflushed ledger fails with BKNoSuchEntryException.
• The catch branch returning the memtable LAC without the write-back. A long poll after a LAC read then keeps waiting.

Removing the write-back in the try branch does fail this test, so it's a good guard for the partially flushed case.

Could you keep this test and add a fully unflushed case next to it? With the same setup:

1. Add entries 0–2 without flushing.
2. Evict with the same invalidate calls.
3. Assert LAC 1.
4. Assert waitForLastAddConfirmedUpdate(ledgerId, 0, watcher) returns false (the write-back reached the cache).
5. Call flush(), assert the memtable is empty, and assert LAC 1 again.

In my local checks, assertions like these fail under both changes above.

[codelipenghui]

Nit: a one-line comment on why the value is written back would help, for example: it keeps the cached LAC from falling back to the older index value once the memtable is flushed, and it notifies LAC watchers. The method returns the right value either way, so a later reader could take the write-back for dead code.

[codelipenghui]

Thanks for the iterations. Checking the cached LAC first, then the memtable (with the write-back), then the index looks good to me.

Verified on f1aef21:

• The original #4900 case (an evicted ledger with nothing flushed) and @djsweet's partially flushed case both return the newest LAC, including after the rest of the ledger is flushed.
• An end-to-end V3 read of an evicted, unflushed ledger succeeds. On master it fails with BKNoSuchEntryException.
• The common path, where the LAC is cached, costs the same as master in a local micro-benchmark (about 40 ns per call).
• Removing the memtable step, its write-back, or the cache check each makes at least one test in SortedLedgerStorageTest fail.
• SortedLedgerStorageTest (12 tests), the same 12 related suites as before (118 tests) and checkstyle pass.

Two optional nits inline. Could you also update the PR description? It still describes the previous memtable-first version and 8 tests.

A possible follow-up, not for this PR: waitForLastAddConfirmedUpdate only checks the cached LAC. So the first long poll after an eviction waits until its timeout or the next add, even though the memtable already has a newer LAC.

[codelipenghui]

Nit: with the new order, this comment no longer describes the case. The index is only read after the memtable had nothing for this ledger, and unflushed entries stay visible in the memtable until all of them are in the index, so a flush can't cause this miss. The recheck now only matters if a first entry is added after the memtable check above. Maybe: // An entry may have been added after the memtable check above.

[codelipenghui]

Nit: shutdown() now closes the mock, so the real memtable created by setCheckpointSource is never closed. In the entryLogPerLedger=true run that's an EntryMemTableWithParallelFlusher, and its 8 flush threads keep running after the test. I counted 8 alive after shutdown(), and 0 without the swap.

The class already doesn't shut down its setUp storage, so this is optional. Either of these would avoid it:

• keep a reference to the original memtable and close it in finally;
• use spy(storage.memTable) with verify(..., never()).getLastEntry(0L).