Examples with KeyValueLogMessage com.apple.foundationdb.record.logging.KeyValueLogMessage used on opensource projects

Example 16 with KeyValueLogMessage

use of com.apple.foundationdb.record.logging.KeyValueLogMessage in project fdb-record-layer by FoundationDB.

the class FDBReverseDirectoryCacheTest method commit.

private void commit(FDBRecordContext context) {
    try {
        context.commit();
        if (logger.isInfoEnabled()) {
            KeyValueLogMessage msg = KeyValueLogMessage.build("committing transaction");
            msg.addKeysAndValues(timer.getKeysAndValues());
            logger.info(msg.toString());
        }
    } finally {
        timer.reset();
    }
}

Example 17 with KeyValueLogMessage

use of com.apple.foundationdb.record.logging.KeyValueLogMessage in project fdb-record-layer by FoundationDB.

the class OnlineIndexerBuildIndexTest method singleRebuild.

void singleRebuild(@Nonnull List<TestRecords1Proto.MySimpleRecord> records, @Nullable List<TestRecords1Proto.MySimpleRecord> recordsWhileBuilding, int agents, boolean overlap, boolean splitLongRecords, @Nonnull Index index, @Nonnull Runnable beforeBuild, @Nonnull Runnable afterBuild, @Nonnull Runnable afterReadable) {
    LOGGER.info(KeyValueLogMessage.of("beginning rebuild test", TestLogMessageKeys.RECORDS, records.size(), LogMessageKeys.RECORDS_WHILE_BUILDING, recordsWhileBuilding == null ? 0 : recordsWhileBuilding.size(), TestLogMessageKeys.AGENTS, agents, TestLogMessageKeys.OVERLAP, overlap, TestLogMessageKeys.SPLIT_LONG_RECORDS, splitLongRecords, TestLogMessageKeys.INDEX, index));
    final FDBStoreTimer timer = new FDBStoreTimer();
    final FDBRecordStoreTestBase.RecordMetaDataHook onlySplitHook = metaDataBuilder -> {
        if (splitLongRecords) {
            metaDataBuilder.setSplitLongRecords(true);
            metaDataBuilder.removeIndex("MySimpleRecord$str_value_indexed");
        }
    };
    final FDBRecordStoreTestBase.RecordMetaDataHook hook = metaDataBuilder -> {
        onlySplitHook.apply(metaDataBuilder);
        metaDataBuilder.addIndex("MySimpleRecord", index);
    };
    LOGGER.info(KeyValueLogMessage.of("inserting elements prior to test", TestLogMessageKeys.RECORDS, records.size()));
    openSimpleMetaData(onlySplitHook);
    try (FDBRecordContext context = openContext()) {
        for (TestRecords1Proto.MySimpleRecord record : records) {
            // Check presence first to avoid overwriting version information of previously added records.
            Tuple primaryKey = Tuple.from(record.getRecNo());
            if (recordStore.loadRecord(primaryKey) == null) {
                recordStore.saveRecord(record);
            }
        }
        context.commit();
    }
    LOGGER.info(KeyValueLogMessage.of("running before build for test"));
    beforeBuild.run();
    openSimpleMetaData(hook);
    LOGGER.info(KeyValueLogMessage.of("adding index", TestLogMessageKeys.INDEX, index));
    openSimpleMetaData(hook);
    final boolean isAlwaysReadable;
    try (FDBRecordContext context = openContext()) {
        // care of by OnlineIndexer.
        if (!safeBuild) {
            LOGGER.info(KeyValueLogMessage.of("marking write-only", TestLogMessageKeys.INDEX, index));
            recordStore.clearAndMarkIndexWriteOnly(index).join();
        }
        isAlwaysReadable = safeBuild && recordStore.isIndexReadable(index);
        context.commit();
    }
    LOGGER.info(KeyValueLogMessage.of("creating online index builder", TestLogMessageKeys.INDEX, index, TestLogMessageKeys.RECORD_TYPES, metaData.recordTypesForIndex(index), LogMessageKeys.SUBSPACE, ByteArrayUtil2.loggable(subspace.pack()), LogMessageKeys.LIMIT, 20, TestLogMessageKeys.RECORDS_PER_SECOND, OnlineIndexer.DEFAULT_RECORDS_PER_SECOND * 100));
    final OnlineIndexer.Builder builder = OnlineIndexer.newBuilder().setDatabase(fdb).setMetaData(metaData).setIndex(index).setSubspace(subspace).setConfigLoader(old -> {
        OnlineIndexer.Config.Builder conf = OnlineIndexer.Config.newBuilder().setMaxLimit(20).setMaxRetries(Integer.MAX_VALUE).setRecordsPerSecond(OnlineIndexer.DEFAULT_RECORDS_PER_SECOND * 100);
        if (ThreadLocalRandom.current().nextBoolean()) {
            // randomly enable the progress logging to ensure that it doesn't throw exceptions,
            // or otherwise disrupt the build.
            LOGGER.info("Setting progress log interval");
            conf.setProgressLogIntervalMillis(0);
        }
        return conf.build();
    }).setTimer(timer);
    if (ThreadLocalRandom.current().nextBoolean()) {
        LOGGER.info("Setting priority to DEFAULT");
        builder.setPriority(FDBTransactionPriority.DEFAULT);
    }
    if (fdb.isTrackLastSeenVersion()) {
        LOGGER.info("Setting weak read semantics");
        builder.setWeakReadSemantics(new FDBDatabase.WeakReadSemantics(0L, Long.MAX_VALUE, true));
    }
    if (!safeBuild) {
        builder.setIndexingPolicy(OnlineIndexer.IndexingPolicy.newBuilder().setIfDisabled(OnlineIndexer.IndexingPolicy.DesiredAction.ERROR).setIfMismatchPrevious(OnlineIndexer.IndexingPolicy.DesiredAction.ERROR));
        builder.setUseSynchronizedSession(false);
    }
    try (OnlineIndexer indexBuilder = builder.build()) {
        CompletableFuture<Void> buildFuture;
        LOGGER.info(KeyValueLogMessage.of("building index", TestLogMessageKeys.INDEX, index, TestLogMessageKeys.AGENT, agents, LogMessageKeys.RECORDS_WHILE_BUILDING, recordsWhileBuilding == null ? 0 : recordsWhileBuilding.size(), TestLogMessageKeys.OVERLAP, overlap));
        if (agents == 1) {
            buildFuture = indexBuilder.buildIndexAsync(false);
        } else {
            if (overlap) {
                CompletableFuture<?>[] futures = new CompletableFuture<?>[agents];
                for (int i = 0; i < agents; i++) {
                    final int agent = i;
                    futures[i] = safeBuild ? indexBuilder.buildIndexAsync(false).exceptionally(exception -> {
                        // because the other one is already working on building the index.
                        if (exception.getCause() instanceof SynchronizedSessionLockedException) {
                            LOGGER.info(KeyValueLogMessage.of("Detected another worker processing this index", TestLogMessageKeys.INDEX, index, TestLogMessageKeys.AGENT, agent), exception);
                            return null;
                        } else {
                            throw new CompletionException(exception);
                        }
                    }) : indexBuilder.buildIndexAsync(false);
                }
                buildFuture = CompletableFuture.allOf(futures);
            } else {
                // Safe builds do not support building ranges yet.
                assumeFalse(safeBuild);
                buildFuture = indexBuilder.buildEndpoints().thenCompose(tupleRange -> {
                    if (tupleRange != null) {
                        long start = tupleRange.getLow().getLong(0);
                        long end = tupleRange.getHigh().getLong(0);
                        CompletableFuture<?>[] futures = new CompletableFuture<?>[agents];
                        for (int i = 0; i < agents; i++) {
                            long itrStart = start + (end - start) / agents * i;
                            long itrEnd = (i == agents - 1) ? end : start + (end - start) / agents * (i + 1);
                            LOGGER.info(KeyValueLogMessage.of("building range", TestLogMessageKeys.INDEX, index, TestLogMessageKeys.AGENT, i, TestLogMessageKeys.BEGIN, itrStart, TestLogMessageKeys.END, itrEnd));
                            futures[i] = indexBuilder.buildRange(Key.Evaluated.scalar(itrStart), Key.Evaluated.scalar(itrEnd));
                        }
                        return CompletableFuture.allOf(futures);
                    } else {
                        return AsyncUtil.DONE;
                    }
                });
            }
        }
        if (safeBuild) {
            buildFuture = MoreAsyncUtil.composeWhenComplete(buildFuture, (result, ex) -> indexBuilder.checkAnyOngoingOnlineIndexBuildsAsync().thenAccept(Assertions::assertFalse), fdb::mapAsyncToSyncException);
        }
        if (recordsWhileBuilding != null && recordsWhileBuilding.size() > 0) {
            int i = 0;
            while (i < recordsWhileBuilding.size()) {
                List<TestRecords1Proto.MySimpleRecord> thisBatch = recordsWhileBuilding.subList(i, Math.min(i + 30, recordsWhileBuilding.size()));
                fdb.run(context -> {
                    FDBRecordStore store = recordStore.asBuilder().setContext(context).build();
                    thisBatch.forEach(store::saveRecord);
                    return null;
                });
                i += 30;
            }
        }
        buildFuture.join();
        // if a record is added to a range that has already been built, it will not be counted, otherwise,
        // it will.
        long additionalScans = 0;
        if (recordsWhileBuilding != null && recordsWhileBuilding.size() > 0) {
            additionalScans += (long) recordsWhileBuilding.size();
        }
        try (FDBRecordContext context = openContext()) {
            IndexBuildState indexBuildState = context.asyncToSync(FDBStoreTimer.Waits.WAIT_GET_INDEX_BUILD_STATE, IndexBuildState.loadIndexBuildStateAsync(recordStore, index));
            IndexState indexState = indexBuildState.getIndexState();
            if (isAlwaysReadable) {
                assertEquals(IndexState.READABLE, indexState);
            } else {
                assertEquals(IndexState.WRITE_ONLY, indexState);
                assertEquals(indexBuilder.getTotalRecordsScanned(), indexBuildState.getRecordsScanned());
                // Count index is not defined so we cannot determine the records in total from it.
                assertNull(indexBuildState.getRecordsInTotal());
            }
        }
        assertThat(indexBuilder.getTotalRecordsScanned(), allOf(greaterThanOrEqualTo((long) records.size()), lessThanOrEqualTo((long) records.size() + additionalScans)));
    }
    KeyValueLogMessage msg = KeyValueLogMessage.build("building index - completed", TestLogMessageKeys.INDEX, index);
    msg.addKeysAndValues(timer.getKeysAndValues());
    LOGGER.info(msg.toString());
    LOGGER.info(KeyValueLogMessage.of("running post build checks", TestLogMessageKeys.INDEX, index));
    // uses the index in quereis since the index is readable.
    if (!isAlwaysReadable) {
        afterBuild.run();
    }
    LOGGER.info(KeyValueLogMessage.of("verifying range set emptiness", TestLogMessageKeys.INDEX, index));
    try (FDBRecordContext context = openContext()) {
        RangeSet rangeSet = new RangeSet(recordStore.indexRangeSubspace(metaData.getIndex(index.getName())));
        System.out.println("Range set for " + records.size() + " records:\n" + rangeSet.rep(context.ensureActive()).join());
        if (!isAlwaysReadable) {
            assertEquals(Collections.emptyList(), rangeSet.missingRanges(context.ensureActive()).asList().join());
        }
        context.commit();
    }
    LOGGER.info(KeyValueLogMessage.of("marking index readable", TestLogMessageKeys.INDEX, index));
    try (FDBRecordContext context = openContext()) {
        boolean updated = recordStore.markIndexReadable(index).join();
        if (isAlwaysReadable) {
            assertFalse(updated);
        } else {
            assertTrue(updated);
        }
        context.commit();
    }
    afterReadable.run();
    LOGGER.info(KeyValueLogMessage.of("ending rebuild test", TestLogMessageKeys.RECORDS, records.size(), LogMessageKeys.RECORDS_WHILE_BUILDING, recordsWhileBuilding == null ? 0 : recordsWhileBuilding.size(), TestLogMessageKeys.AGENTS, agents, TestLogMessageKeys.OVERLAP, overlap, TestLogMessageKeys.SPLIT_LONG_RECORDS, splitLongRecords, TestLogMessageKeys.INDEX, index));
}

Example 18 with KeyValueLogMessage

use of com.apple.foundationdb.record.logging.KeyValueLogMessage in project fdb-record-layer by FoundationDB.

the class FDBRecordStore method getRecordCountForRebuildIndexes.

/**
 * Get count of records to pass to a {@link UserVersionChecker} to decide whether to build right away. If all of the
 * new indexes are over a single type and that type has a record key prefix, then this count will only be over the
 * record type being indexed. If not, it will be the count of all records of all types, as in that case, the indexer
 * will need to scan the entire store to build each index. If determining the record count would be too costly (such
 * as if there is not an appropriate {@linkplain IndexTypes#COUNT count} index defined), this function may return
 * {@link Long#MAX_VALUE} to indicate that an unknown and unbounded number of records would have to be scanned
 * to build the index.
 *
 * @param newStore {@code true} if this is a brand new store
 * @param rebuildRecordCounts {@code true} if there is a record count key that needs to be rebuilt
 * @param indexes indexes that need to be built
 * @param singleRecordTypeWithPrefixKey either a single record type prefixed by the record type key or {@code null}
 * @return a future that completes to the record count for the version checker
 */
@Nonnull
@SuppressWarnings("PMD.EmptyCatchBlock")
protected CompletableFuture<Long> getRecordCountForRebuildIndexes(boolean newStore, boolean rebuildRecordCounts, @Nonnull Map<Index, List<RecordType>> indexes, @Nullable RecordType singleRecordTypeWithPrefixKey) {
    // Do this with the new indexes in write-only mode to avoid using one of them
    // when evaluating the snapshot record count.
    MutableRecordStoreState writeOnlyState = recordStoreStateRef.get().withWriteOnlyIndexes(indexes.keySet().stream().map(Index::getName).collect(Collectors.toList()));
    if (singleRecordTypeWithPrefixKey != null) {
        // Get a count for just those records, either from a COUNT index on just that type or from a universal COUNT index grouped by record type.
        MutableRecordStoreState saveState = recordStoreStateRef.get();
        try {
            recordStoreStateRef.set(writeOnlyState);
            return getSnapshotRecordCountForRecordType(singleRecordTypeWithPrefixKey.getName());
        } catch (RecordCoreException ex) {
        // No such index; have to use total record count.
        } finally {
            recordStoreStateRef.set(saveState);
        }
    }
    if (!rebuildRecordCounts) {
        MutableRecordStoreState saveState = recordStoreStateRef.get();
        try {
            recordStoreStateRef.set(writeOnlyState);
            // See: FDBRecordStoreBase.checkPossiblyRebuild() could take a long time if the record count index is split into many groups (https://github.com/FoundationDB/fdb-record-layer/issues/7)
            return getSnapshotRecordCount();
        } catch (RecordCoreException ex) {
        // Probably this was from the lack of appropriate index on count; treat like rebuildRecordCounts = true.
        } finally {
            recordStoreStateRef.set(saveState);
        }
    }
    // Do a scan (limited to a single record) to see if the store is empty.
    final ExecuteProperties executeProperties = ExecuteProperties.newBuilder().setReturnedRowLimit(1).setIsolationLevel(IsolationLevel.SNAPSHOT).build();
    final ScanProperties scanProperties = new ScanProperties(executeProperties);
    final RecordCursor<FDBStoredRecord<Message>> records;
    if (singleRecordTypeWithPrefixKey == null) {
        records = scanRecords(null, scanProperties);
    } else {
        records = scanRecords(TupleRange.allOf(singleRecordTypeWithPrefixKey.getRecordTypeKeyTuple()), null, scanProperties);
    }
    return records.onNext().thenApply(result -> {
        if (result.hasNext()) {
            if (LOGGER.isInfoEnabled()) {
                LOGGER.info(KeyValueLogMessage.of("version check scan found non-empty store", subspaceProvider.logKey(), subspaceProvider.toString(context)));
            }
            return Long.MAX_VALUE;
        } else {
            if (newStore ? LOGGER.isDebugEnabled() : LOGGER.isInfoEnabled()) {
                KeyValueLogMessage msg = KeyValueLogMessage.build("version check scan found empty store", subspaceProvider.logKey(), subspaceProvider.toString(context));
                if (newStore) {
                    LOGGER.debug(msg.toString());
                } else {
                    LOGGER.info(msg.toString());
                }
            }
            return 0L;
        }
    });
}

Example 19 with KeyValueLogMessage

use of com.apple.foundationdb.record.logging.KeyValueLogMessage in project fdb-record-layer by FoundationDB.

the class FDBRecordStore method maybeLogIndexesNeedingRebuilding.

private void maybeLogIndexesNeedingRebuilding(@Nonnull Map<Index, CompletableFuture<IndexState>> newStates, @Nonnull AtomicLong recordCountRef, @Nonnull AtomicLong recordsSizeRef, boolean rebuildRecordCounts, boolean newStore) {
    if (LOGGER.isDebugEnabled()) {
        KeyValueLogMessage msg = KeyValueLogMessage.build("indexes need rebuilding", subspaceProvider.logKey(), subspaceProvider.toString(context));
        // Log the statistics that the user version checker used to determine whether the index could be rebuilt
        // online. For both the record count and the records size estimate, a non-negative value implies that
        // the checker resolved the value
        long recordCount = recordCountRef.get();
        if (recordCount >= 0L) {
            msg.addKeyAndValue(LogMessageKeys.RECORD_COUNT, recordCount == Long.MAX_VALUE ? "unknown" : Long.toString(recordCount));
        }
        long recordsSize = recordsSizeRef.get();
        if (recordsSize >= 0L) {
            msg.addKeyAndValue(LogMessageKeys.RECORDS_SIZE_ESTIMATE, Long.toString(recordsSize));
        }
        if (rebuildRecordCounts) {
            msg.addKeyAndValue(LogMessageKeys.REBUILD_RECORD_COUNTS, "true");
        }
        Map<String, List<String>> stateNames = new HashMap<>();
        for (Map.Entry<Index, CompletableFuture<IndexState>> stateEntry : newStates.entrySet()) {
            final String stateName;
            if (MoreAsyncUtil.isCompletedNormally(stateEntry.getValue())) {
                stateName = stateEntry.getValue().join().getLogName();
            } else {
                stateName = "UNKNOWN";
            }
            stateNames.compute(stateName, (key, names) -> {
                if (names == null) {
                    names = new ArrayList<>();
                }
                names.add(stateEntry.getKey().getName());
                return names;
            });
        }
        msg.addKeysAndValues(stateNames);
        if (newStore) {
            msg.addKeyAndValue(LogMessageKeys.NEW_STORE, "true");
        }
        LOGGER.debug(msg.toString());
    }
}

Example 20 with KeyValueLogMessage

use of com.apple.foundationdb.record.logging.KeyValueLogMessage in project fdb-record-layer by FoundationDB.

the class IndexingBase method handleStateAndDoBuildIndexAsync.

@Nonnull
private CompletableFuture<Void> handleStateAndDoBuildIndexAsync(boolean markReadable, KeyValueLogMessage message) {
    /*
         * Multi target:
         * The primary and follower indexes must the same state.
         * If the primary is disabled, a follower is write_only/readable, and the policy for write_only/readable is
         *   rebuild - the follower's state will be cleared.
         * If the primary is cleared, all the followers are cleared (must match stamps/ranges).
         * If the primary is write_only, and the followers' stamps/ranges do not match, it would be caught during indexing.
         */
    final List<Index> targetIndexes = common.getTargetIndexes();
    final Index primaryIndex = targetIndexes.get(0);
    return getRunner().runAsync(context -> openRecordStore(context).thenCompose(store -> {
        IndexState indexState = store.getIndexState(primaryIndex);
        if (isScrubber) {
            validateOrThrowEx(indexState == IndexState.READABLE, "Scrubber was called for a non-readable index. Index:" + primaryIndex.getName() + " State: " + indexState);
            return setScrubberTypeOrThrow(store).thenApply(ignore -> true);
        }
        OnlineIndexer.IndexingPolicy.DesiredAction desiredAction = policy.getStateDesiredAction(indexState);
        if (desiredAction == OnlineIndexer.IndexingPolicy.DesiredAction.ERROR) {
            throw new ValidationException("Index state is not as expected", LogMessageKeys.INDEX_NAME, primaryIndex.getName(), LogMessageKeys.INDEX_VERSION, primaryIndex.getLastModifiedVersion(), LogMessageKeys.INDEX_STATE, indexState);
        }
        boolean shouldClear = desiredAction == OnlineIndexer.IndexingPolicy.DesiredAction.REBUILD;
        boolean shouldBuild = shouldClear || indexState != IndexState.READABLE;
        message.addKeyAndValue(LogMessageKeys.INITIAL_INDEX_STATE, indexState);
        message.addKeyAndValue(LogMessageKeys.INDEXING_POLICY_DESIRED_ACTION, desiredAction);
        message.addKeyAndValue(LogMessageKeys.SHOULD_BUILD_INDEX, shouldBuild);
        message.addKeyAndValue(LogMessageKeys.SHOULD_CLEAR_EXISTING_DATA, shouldClear);
        if (!shouldBuild) {
            // do not index
            return AsyncUtil.READY_FALSE;
        }
        List<Index> indexesToClear = new ArrayList<>(targetIndexes.size());
        if (shouldClear) {
            indexesToClear.add(primaryIndex);
            // The code can work without this line, but it'll save probing the missing ranges
            forceStampOverwrite = true;
        }
        boolean continuedBuild = !shouldClear && indexState == IndexState.WRITE_ONLY;
        for (Index targetIndex : targetIndexes.subList(1, targetIndexes.size())) {
            // Must follow the primary index' status
            IndexState state = store.getIndexState(targetIndex);
            if (state != indexState) {
                if (policy.getStateDesiredAction(state) != OnlineIndexer.IndexingPolicy.DesiredAction.REBUILD || continuedBuild) {
                    throw new ValidationException("A target index state doesn't match the primary index state", LogMessageKeys.INDEX_NAME, primaryIndex.getName(), LogMessageKeys.INDEX_STATE, indexState, LogMessageKeys.TARGET_INDEX_NAME, targetIndex.getName(), LogMessageKeys.TARGET_INDEX_STATE, state);
                }
                // just clear this one, the primary is disabled
                indexesToClear.add(targetIndex);
            } else if (shouldClear) {
                indexesToClear.add(targetIndex);
            }
        }
        return AsyncUtil.whenAll(indexesToClear.stream().map(store::clearAndMarkIndexWriteOnly).collect(Collectors.toList())).thenCompose(vignore -> markIndexesWriteOnly(continuedBuild, store)).thenCompose(vignore -> setIndexingTypeOrThrow(store, continuedBuild)).thenApply(ignore -> true);
    }), common.indexLogMessageKeyValues("IndexingBase::handleIndexingState")).thenCompose(doIndex -> doIndex ? buildIndexInternalAsync().thenApply(ignore -> markReadable) : AsyncUtil.READY_FALSE).thenCompose(this::markIndexReadable).thenApply(ignore -> null);
}