Fix FoundationDB#1898: Indexing: periodic "Built Range" log message i…

…s broken squashed: + Implement John's and Scott's requested change - adding a test
jjezra · Nov 7, 2022 · 92c3356 · 92c3356
1 parent c4a348b
commit 92c3356
Show file tree

Hide file tree

Showing 4 changed files with 46 additions and 5 deletions.
diff --git a/docs/ReleaseNotes.md b/docs/ReleaseNotes.md
@@ -15,7 +15,7 @@ The Guava dependency version has been updated to 31.1. Projects may need to chec
 // begin next release
 ### NEXT_RELEASE
 
-* **Bug fix** Fix 1 [(Issue #NNN)](https://github.com/FoundationDB/fdb-record-layer/issues/NNN)
+* **Bug fix** Indexing: periodic "Built Range" log message is broken [(Issue #1898)](https://github.com/FoundationDB/fdb-record-layer/issues/1898)
 * **Bug fix** Fix 2 [(Issue #NNN)](https://github.com/FoundationDB/fdb-record-layer/issues/NNN)
 * **Bug fix** Fix 3 [(Issue #NNN)](https://github.com/FoundationDB/fdb-record-layer/issues/NNN)
 * **Bug fix** Fix 4 [(Issue #NNN)](https://github.com/FoundationDB/fdb-record-layer/issues/NNN)

diff --git a/...record-layer-core/src/main/java/com/apple/foundationdb/record/logging/LogMessageKeys.java b/...record-layer-core/src/main/java/com/apple/foundationdb/record/logging/LogMessageKeys.java
@@ -139,6 +139,7 @@ public enum LogMessageKeys {
     WROTE_INDEX,
     NEW_STORE,
     RECORDS_WHILE_BUILDING,
+    RECORDS_PER_SECOND,
     DOCUMENT,
     SESSION_ID,
     INDEXER_SESSION_ID,

diff --git a/...-core/src/main/java/com/apple/foundationdb/record/provider/foundationdb/IndexingBase.java b/...-core/src/main/java/com/apple/foundationdb/record/provider/foundationdb/IndexingBase.java
@@ -590,11 +590,13 @@ protected CompletableFuture<Boolean> throttleDelayAndMaybeLogProgress(SubspacePr
         int toWait = (recordsPerSecond == IndexingCommon.UNLIMITED) ? 0 : 1000 * limit / recordsPerSecond;
 
         if (LOGGER.isInfoEnabled() && shouldLogBuildProgress()) {
-            LOGGER.info(KeyValueLogMessage.build("Built Range",
+            LOGGER.info(KeyValueLogMessage.build("Indexer: Built Range",
                     subspaceProvider.logKey(), subspaceProvider,
                     LogMessageKeys.LIMIT, limit,
-                    LogMessageKeys.DELAY, toWait)
+                    LogMessageKeys.DELAY, toWait,
+                    LogMessageKeys.RECORDS_PER_SECOND, recordsPerSecond)
                     .addKeysAndValues(additionalLogMessageKeyValues)
+                    .addKeysAndValues(indexingLogMessageKeyValues())
                     .addKeysAndValues(common.indexLogMessageKeyValues())
                     .toString());
         }
@@ -622,7 +624,7 @@ private void validateTimeLimit(int toWait) {
     private boolean shouldLogBuildProgress() {
         long interval = common.config.getProgressLogIntervalMillis();
         long now = System.currentTimeMillis();
-        if (interval == 0 || interval < (now - timeOfLastProgressLogMillis)) {
+        if (interval == 0 || interval > (now - timeOfLastProgressLogMillis)) {
             return false;
         }
         timeOfLastProgressLogMillis = now;
@@ -811,7 +813,7 @@ protected CompletableFuture<Void> iterateAllRanges(List<Object> additionalLogMes
                                         // all done
                                         return AsyncUtil.READY_FALSE;
                                     }
-                                    return throttleDelayAndMaybeLogProgress(subspaceProvider, Collections.emptyList());
+                                    return throttleDelayAndMaybeLogProgress(subspaceProvider, additionalLogMessageKeyValues);
                                 }
                                 final RuntimeException unwrappedEx = getRunner().getDatabase().mapAsyncToSyncException(ex);
                                 if (LOGGER.isInfoEnabled()) {

diff --git a/...est/java/com/apple/foundationdb/record/provider/foundationdb/OnlineIndexerSimpleTest.java b/...est/java/com/apple/foundationdb/record/provider/foundationdb/OnlineIndexerSimpleTest.java
@@ -29,6 +29,7 @@
 import com.apple.foundationdb.record.IsolationLevel;
 import com.apple.foundationdb.record.RecordCoreException;
 import com.apple.foundationdb.record.RecordCoreRetriableTransactionException;
+import com.apple.foundationdb.record.TestHelpers;
 import com.apple.foundationdb.record.TestRecords1Proto;
 import com.apple.foundationdb.record.TupleRange;
 import com.apple.foundationdb.record.logging.LogMessageKeys;
@@ -1051,4 +1052,41 @@ public void testTimeLimit() {
             assertTrue(e.getMessage().contains("Time Limit Exceeded"));
         }
     }
+
+    @Test
+    public void testLogInterval() {
+        List<TestRecords1Proto.MySimpleRecord> records = LongStream.range(0, 50).mapToObj(val ->
+                TestRecords1Proto.MySimpleRecord.newBuilder().setRecNo(val).setNumValue2((int)val + 1).build()
+        ).collect(Collectors.toList());
+
+        openSimpleMetaData();
+        try (FDBRecordContext context = openContext()) {
+            records.forEach(recordStore::saveRecord);
+            context.commit();
+        }
+
+        Index index = new Index("newIndex", field("num_value_2").ungrouped(), IndexTypes.SUM);
+        FDBRecordStoreTestBase.RecordMetaDataHook hook = metaDataBuilder -> metaDataBuilder.addIndex("MySimpleRecord", index);
+        openSimpleMetaData(hook);
+        try (OnlineIndexer indexer = OnlineIndexer.newBuilder()
+                .setDatabase(fdb).setMetaData(metaData).setIndex(index).setSubspace(subspace)
+                .setProgressLogIntervalMillis(10)
+                .setLimit(20)
+                .setConfigLoader(old -> {
+                    // Ensure that time limit is exceeded
+                    try {
+                        Thread.sleep(10);
+                    } catch (InterruptedException e) {
+                        fail("The test was interrupted");
+                    }
+                    return old;
+                })
+                .build()) {
+            TestHelpers.assertLogs(IndexingBase.class, "Indexer: Built Range",
+                    () -> {
+                        indexer.buildIndex();
+                        return null;
+                    });
+        }
+    }
 }