Add latency stats for entry location index lookup so that possible Ro…

…cksDB 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 19fd8f7)

bookkeeper-common/src/test/java/org/apache/bookkeeper/test/TestStatsProvider.java

@@ -146,6 +146,10 @@ public synchronized double getSuccessAverage() {
         public synchronized long getSuccessCount() {
             return successCount;
         }
+
+        public synchronized long getFailureCount() {
+            return failureCount;
+        }
     }
 
     /**

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

@@ -34,6 +34,7 @@
 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,18 +76,27 @@ public long getLocation(long ledgerId, long entryId) throws IOException {
         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()) {
                     log.debug("Entry not found {}@{} in db index", ledgerId, entryId);
                 }
                 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);
+            }
         }
     }
 

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

@@ -25,6 +25,7 @@
 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,13 +41,20 @@
 class EntryLocationIndexStats {
 
     private static final String ENTRIES_COUNT = "entries-count";
+    private static final String LOOKUP_ENTRY_LOCATION = "lookup-entry-location";
 
     @StatsDoc(
         name = ENTRIES_COUNT,
         help = "Current number of entries"
     )
     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 @@ public Long getSample() {
             }
         };
         statsLogger.registerGauge(ENTRIES_COUNT, entriesCountGauge);
+        lookupEntryLocationStats = statsLogger.getOpStatsLogger(LOOKUP_ENTRY_LOCATION);
     }
 
 }

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 void testDeleteSpecialEntry() throws IOException {
         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());
+    }
 }

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.