From 92c335657b47c5e5dbf6f29e91e91da7cfe81fc1 Mon Sep 17 00:00:00 2001 From: Josef Ezra Date: Mon, 7 Nov 2022 16:02:50 -0500 Subject: [PATCH] Fix #1898: Indexing: periodic "Built Range" log message is broken squashed: + Implement John's and Scott's requested change - adding a test --- docs/ReleaseNotes.md | 2 +- .../record/logging/LogMessageKeys.java | 1 + .../provider/foundationdb/IndexingBase.java | 10 +++-- .../foundationdb/OnlineIndexerSimpleTest.java | 38 +++++++++++++++++++ 4 files changed, 46 insertions(+), 5 deletions(-) diff --git a/docs/ReleaseNotes.md b/docs/ReleaseNotes.md index c1f66f649a..c777e366c4 100644 --- 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/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/logging/LogMessageKeys.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/logging/LogMessageKeys.java index d1816e1643..0db0e992cc 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/logging/LogMessageKeys.java +++ b/fdb-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/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/provider/foundationdb/IndexingBase.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/provider/foundationdb/IndexingBase.java index a878c56d79..0d03a013f3 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/provider/foundationdb/IndexingBase.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/provider/foundationdb/IndexingBase.java @@ -590,11 +590,13 @@ protected CompletableFuture 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 iterateAllRanges(List 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/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/provider/foundationdb/OnlineIndexerSimpleTest.java b/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/provider/foundationdb/OnlineIndexerSimpleTest.java index d882262b07..503d05347c 100644 --- a/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/provider/foundationdb/OnlineIndexerSimpleTest.java +++ b/fdb-record-layer-core/src/test/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 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; + }); + } + } }