This is an automated email from the ASF dual-hosted git repository. yong pushed a commit to branch branch-4.15 in repository https://gitbox.apache.org/repos/asf/bookkeeper.git
commit 58db136bf7856e39120947fe431ae16c7d2ef1fa Author: Lari Hotari <[email protected]> AuthorDate: Tue Aug 16 13:46:33 2022 +0300 Add latency stats for entry location index lookup so that possible RocksDB bottleneck can be detected (#3444) * Add operation latency stats for entry location lookup - this metric will help detecting when the bottleneck is in the entry location index lookup operations and RocksDB tuning is needed * Address review feedback: fix issue with eventLatencyMillis variable * Rename misleading parameter name (cherry picked from commit 19fd8f74265130f76f55b04a24cc0ee5c7a634a5) --- .../apache/bookkeeper/test/TestStatsProvider.java | 4 +++ .../bookie/storage/ldb/EntryLocationIndex.java | 12 ++++++++- .../storage/ldb/EntryLocationIndexStats.java | 9 +++++++ .../bookie/storage/ldb/EntryLocationIndexTest.java | 29 ++++++++++++++++++++++ .../org/apache/bookkeeper/stats/OpStatsLogger.java | 8 +++--- 5 files changed, 57 insertions(+), 5 deletions(-) diff --git a/bookkeeper-common/src/test/java/org/apache/bookkeeper/test/TestStatsProvider.java b/bookkeeper-common/src/test/java/org/apache/bookkeeper/test/TestStatsProvider.java index f486075651..c2a06d6f41 100644 --- a/bookkeeper-common/src/test/java/org/apache/bookkeeper/test/TestStatsProvider.java +++ b/bookkeeper-common/src/test/java/org/apache/bookkeeper/test/TestStatsProvider.java @@ -146,6 +146,10 @@ public class TestStatsProvider implements StatsProvider { public synchronized long getSuccessCount() { return successCount; } + + public synchronized long getFailureCount() { + return failureCount; + } } /** diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndex.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndex.java index 468f268aab..dc8e947ffc 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndex.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndex.java @@ -34,6 +34,7 @@ import org.apache.bookkeeper.bookie.storage.ldb.KeyValueStorage.Batch; import org.apache.bookkeeper.bookie.storage.ldb.KeyValueStorageFactory.DbConfigType; import org.apache.bookkeeper.conf.ServerConfiguration; import org.apache.bookkeeper.stats.StatsLogger; +import org.apache.bookkeeper.util.MathUtils; import org.apache.bookkeeper.util.collections.ConcurrentLongHashSet; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -75,6 +76,8 @@ public class EntryLocationIndex implements Closeable { LongPairWrapper key = LongPairWrapper.get(ledgerId, entryId); LongWrapper value = LongWrapper.get(); + long startTimeNanos = MathUtils.nowInNano(); + boolean operationSuccess = false; try { if (locationsDb.get(key.array, value.array) < 0) { if (log.isDebugEnabled()) { @@ -82,11 +85,18 @@ public class EntryLocationIndex implements Closeable { } return 0; } - + operationSuccess = true; return value.getValue(); } finally { key.recycle(); value.recycle(); + if (operationSuccess) { + stats.getLookupEntryLocationStats() + .registerSuccessfulEvent(MathUtils.elapsedNanos(startTimeNanos), TimeUnit.NANOSECONDS); + } else { + stats.getLookupEntryLocationStats() + .registerFailedEvent(MathUtils.elapsedNanos(startTimeNanos), TimeUnit.NANOSECONDS); + } } } diff --git a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndexStats.java b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndexStats.java index dd87f7b92b..80bdda4825 100644 --- a/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndexStats.java +++ b/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndexStats.java @@ -25,6 +25,7 @@ import static org.apache.bookkeeper.bookie.BookKeeperServerStats.CATEGORY_SERVER import java.util.function.Supplier; import lombok.Getter; import org.apache.bookkeeper.stats.Gauge; +import org.apache.bookkeeper.stats.OpStatsLogger; import org.apache.bookkeeper.stats.StatsLogger; import org.apache.bookkeeper.stats.annotations.StatsDoc; @@ -40,6 +41,7 @@ import org.apache.bookkeeper.stats.annotations.StatsDoc; class EntryLocationIndexStats { private static final String ENTRIES_COUNT = "entries-count"; + private static final String LOOKUP_ENTRY_LOCATION = "lookup-entry-location"; @StatsDoc( name = ENTRIES_COUNT, @@ -47,6 +49,12 @@ class EntryLocationIndexStats { ) private final Gauge<Long> entriesCountGauge; + @StatsDoc( + name = LOOKUP_ENTRY_LOCATION, + help = "operation stats of looking up entry location" + ) + private final OpStatsLogger lookupEntryLocationStats; + EntryLocationIndexStats(StatsLogger statsLogger, Supplier<Long> entriesCountSupplier) { entriesCountGauge = new Gauge<Long>() { @@ -61,6 +69,7 @@ class EntryLocationIndexStats { } }; statsLogger.registerGauge(ENTRIES_COUNT, entriesCountGauge); + lookupEntryLocationStats = statsLogger.getOpStatsLogger(LOOKUP_ENTRY_LOCATION); } } diff --git a/bookkeeper-server/src/test/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndexTest.java b/bookkeeper-server/src/test/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndexTest.java index f1cefed161..c9f505c5f5 100644 --- a/bookkeeper-server/src/test/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndexTest.java +++ b/bookkeeper-server/src/test/java/org/apache/bookkeeper/bookie/storage/ldb/EntryLocationIndexTest.java @@ -21,12 +21,14 @@ package org.apache.bookkeeper.bookie.storage.ldb; import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertTrue; import java.io.File; import java.io.IOException; import org.apache.bookkeeper.conf.ServerConfiguration; import org.apache.bookkeeper.stats.NullStatsLogger; +import org.apache.bookkeeper.test.TestStatsProvider; import org.junit.Test; /** @@ -140,4 +142,31 @@ public class EntryLocationIndexTest { idx.removeOffsetFromDeletedLedgers(); assertEquals(0, idx.getLocation(40312, 10)); } + + @Test + public void testEntryIndexLookupLatencyStats() throws IOException { + File tmpDir = File.createTempFile("bkTest", ".dir"); + tmpDir.delete(); + tmpDir.mkdir(); + tmpDir.deleteOnExit(); + + TestStatsProvider statsProvider = new TestStatsProvider(); + EntryLocationIndex idx = new EntryLocationIndex(serverConfiguration, KeyValueStorageRocksDB.factory, + tmpDir.getAbsolutePath(), statsProvider.getStatsLogger("scope")); + + // Add some dummy indexes + idx.addLocation(40313, 11, 5); + + // successful lookup + assertEquals(5, idx.getLocation(40313, 11)); + TestStatsProvider.TestOpStatsLogger lookupEntryLocationOpStats = + statsProvider.getOpStatsLogger("scope.lookup-entry-location"); + assertEquals(1, lookupEntryLocationOpStats.getSuccessCount()); + assertTrue(lookupEntryLocationOpStats.getSuccessAverage() > 0); + + // failed lookup + assertEquals(0, idx.getLocation(12345, 1)); + assertEquals(1, lookupEntryLocationOpStats.getFailureCount()); + assertEquals(1, lookupEntryLocationOpStats.getSuccessCount()); + } } diff --git a/bookkeeper-stats/src/main/java/org/apache/bookkeeper/stats/OpStatsLogger.java b/bookkeeper-stats/src/main/java/org/apache/bookkeeper/stats/OpStatsLogger.java index cef83042d7..3c9c730307 100644 --- a/bookkeeper-stats/src/main/java/org/apache/bookkeeper/stats/OpStatsLogger.java +++ b/bookkeeper-stats/src/main/java/org/apache/bookkeeper/stats/OpStatsLogger.java @@ -25,18 +25,18 @@ public interface OpStatsLogger { /** * Increment the failed op counter with the given eventLatency. - * @param eventLatencyMillis The event latency + * @param eventLatency The event latency * @param unit */ - void registerFailedEvent(long eventLatencyMillis, TimeUnit unit); + void registerFailedEvent(long eventLatency, TimeUnit unit); /** * An operation succeeded with the given eventLatency. Update * stats to reflect the same - * @param eventLatencyMillis The event latency + * @param eventLatency The event latency * @param unit */ - void registerSuccessfulEvent(long eventLatencyMillis, TimeUnit unit); + void registerSuccessfulEvent(long eventLatency, TimeUnit unit); /** * An operation with the given value succeeded.
