Serious Performance problem caused by #3239

[gaozhangmin]

BUG REPORT

Describe the bug
#3239 addressed the replication problem of empty ledger, which means the first entry id is INVALID_ENTRY_ID.

The replicationWorker will replicate these empty ledgers, LINE 441 opened these empty ledgers with openLedgerNoRecovery. In method openLedgerNoRecovery, readLastConfirmed request will be send to server if the fragment is opened.

bookkeeper/bookkeeper-server/src/main/java/org/apache/bookkeeper/replication/ReplicationWorker.java

Lines 432 to 481 in c7cc668

	@SuppressFBWarnings("RCN_REDUNDANT_NULLCHECK_WOULD_HAVE_BEEN_A_NPE")
	private boolean rereplicate(long ledgerIdToReplicate) throws InterruptedException, BKException,
	UnavailableException {
	if (LOG.isDebugEnabled()) {
	LOG.debug("Going to replicate the fragments of the ledger: {}", ledgerIdToReplicate);
	}
	boolean deferLedgerLockRelease = false;
	try (LedgerHandle lh = admin.openLedgerNoRecovery(ledgerIdToReplicate)) {
	Set<LedgerFragment> fragments = getUnderreplicatedFragments(lh,
	conf.getAuditorLedgerVerificationPercentage());
	if (LOG.isDebugEnabled()) {
	LOG.debug("Founds fragments {} for replication from ledger: {}", fragments, ledgerIdToReplicate);
	}
	boolean foundOpenFragments = false;
	long numFragsReplicated = 0;
	for (LedgerFragment ledgerFragment : fragments) {
	if (!ledgerFragment.isClosed()) {
	foundOpenFragments = true;
	continue;
	}
	if (!tryReadingFaultyEntries(lh, ledgerFragment)) {
	LOG.error("Failed to read faulty entries, so giving up replicating ledgerFragment {}",
	ledgerFragment);
	continue;
	}
	try {
	admin.replicateLedgerFragment(lh, ledgerFragment, onReadEntryFailureCallback);
	numFragsReplicated++;
	} catch (BKException.BKBookieHandleNotAvailableException e) {
	LOG.warn("BKBookieHandleNotAvailableException while replicating the fragment", e);
	} catch (BKException.BKLedgerRecoveryException e) {
	LOG.warn("BKLedgerRecoveryException while replicating the fragment", e);
	} catch (BKException.BKNotEnoughBookiesException e) {
	LOG.warn("BKNotEnoughBookiesException while replicating the fragment", e);
	}
	}
	if (numFragsReplicated > 0) {
	numLedgersReplicated.inc();
	}
	if (foundOpenFragments || isLastSegmentOpenAndMissingBookies(lh)) {
	deferLedgerLockRelease = true;
	deferLedgerLockRelease(ledgerIdToReplicate);
	return false;
	}

Let us check how the server processes the readLastConfirmed request. LINE 547 tries to getLastEntry if the request entry id is LAST_ADD_CONFIRMED

bookkeeper/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/SingleDirectoryDbLedgerStorage.java

Lines 542 to 549 in c7cc668

	private ByteBuf doGetEntry(long ledgerId, long entryId) throws IOException, BookieException {
	if (log.isDebugEnabled()) {
	log.debug("Get Entry: {}@{}", ledgerId, entryId);
	}
	if (entryId == BookieProtocol.LAST_ADD_CONFIRMED) {
	return getLastEntry(ledgerId);
	}

Finally, it goes to here. Try to get the last entry id from RocksDB, For a non-existed entry, it searched the a range of ledgers from current ledger id to Long.MAX_VALUE. This search will run for 5mins in my prod env. This caused the slowly process of read request and filled up the read request queue finally.

bookkeeper/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndex.java

Lines 116 to 138 in c7cc668

	private long getLastEntryInLedgerInternal(long ledgerId) throws IOException {
	LongPairWrapper maxEntryId = LongPairWrapper.get(ledgerId, Long.MAX_VALUE);
	// Search the last entry in storage
	Entry<byte[], byte[]> entry = locationsDb.getFloor(maxEntryId.array);
	maxEntryId.recycle();
	if (entry == null) {
	throw new Bookie.NoEntryException(ledgerId, -1);
	} else {
	long foundLedgerId = ArrayUtil.getLong(entry.getKey(), 0);
	long lastEntryId = ArrayUtil.getLong(entry.getKey(), 8);
	if (foundLedgerId == ledgerId) {
	if (log.isDebugEnabled()) {
	log.debug("Found last page in storage db for ledger {} - last entry: {}", ledgerId, lastEntryId);
	}
	return lastEntryId;
	} else {
	throw new Bookie.NoEntryException(ledgerId, -1);
	}
	}
	}

[hangc0276]

Hi @gaozhangmin , thanks for raising this issue.
#3239 mark the OPEN state Empty ledgers, whose ensemble has dead bookies, as under-replicated in Auditor's checkAllLedgers stage. IMO, it makes sense, otherwise, those ledgers can't be replicated and block the decommissioning process.

When those OPEN state Empty ledgers are fenced, the bookie client will trigger a fence readLAC, which will fall into the locationsDb.getFloor(maxEntryId.array) call, and the key does not exist in the RocksDB due to the ledger is empty.

From the performance picture you provided, the locationsDb.getFloor(maxEntryId.array) costs 316s, which is unacceptable. The root cause may be related to the RocksDB, not the OPEN state Empty ledgers marked as under-replicated behavior.

I have a few questions about this issue.

• Would you please the size of your RocksDB, including storage size and the number of keys?
• For those OPEN state and not Empty ledgers, if you call getLAC, it will also fall into the locationsDb.getFloor(maxEntryId.array), does it also cost so much time?
• Would you write a test to open your RocksDB, and call locationsDb.getFloor(maxEntryId.array) for an existed and non-existed legerId, to see the time cost?

[dlg99]

@gaozhangmin Thank you, this looks like an interesting problem.

+1 to the @hangc0276 's questions

For a non-existed entry, it searched the a range of ledgers from current ledger id to Long.MAX_VALUE

I think there is a misunderstanding.

    private long getLastEntryInLedgerInternal(long ledgerId) throws IOException {
        LongPairWrapper maxEntryId = LongPairWrapper.get(ledgerId, Long.MAX_VALUE);

        // Search the last entry in storage
        Entry<byte[], byte[]> entry = locationsDb.getFloor(maxEntryId.array);

LongPairWrapper.get(ledgerId, Long.MAX_VALUE) is a key that consists of (ledgerId, entryId) and not a (ledgerId, the last ledger id).

locationsDb.getFloor will use it as a max boundary to find a max key smaller or equal to this, if that matches the same ledgerId => we have last entryId, otherwise no entry found.
This is implemented in KeyValueStorageRocksDB:

    public Entry<byte[], byte[]> getFloor(byte[] key) throws IOException {
        try (Slice upperBound = new Slice(key);
                 ReadOptions option = new ReadOptions(optionCache).setIterateUpperBound(upperBound);
                 RocksIterator iterator = db.newIterator(option)) {
            iterator.seekToLast();
            if (iterator.isValid()) {
                return new EntryWrapper(iterator.key(), iterator.value());
            }
        }
        return null;
    }

Now the real question is what's going on with seekToLast.
I think the problem is similar to facebook/rocksdb#261

Since deletes are not actually deletes, 
but rather tombstones (which get cleaned up after a compaction), 
your iterator might have to skip a bunch of deletes the get 
to the first key in the database.

This leads us to #2686 (reverted in #3144)
There should be a way to check number of tombstones or get metrics from RocksDb (sorry, I never dealt with this).
there should be a way to trigger compaction on RocksDB. or maybe the search in your case got slowed down by running compaction.

Some recommendations for this case: facebook/rocksdb#5265 (comment)

I don't understand if newer version have significant improvements in this area.
I guess we should repro this in test and try.
Alternatively: as I understand, regular rocksdb.get() is not affected by the tombstones, so we can try something along the lines of:

Check if db.get(LongPairWrapper.get(ledgerId, 0)) exists (or use db.keyMayExist/get combo)
if exists, do a skip search 
    (check every N entries until not found, 
    binary search between last found and first not found to get last known entry id)
if does not exist - bingo, deleted/unknown ledger

this will result in more requests to the RocksDB but should have more predictable runtime.

[TakaHiR07]

I also encounter this issue in bookie-4.16.4, how does this issue be fixed ? @gaozhangmin