diff --git a/infrastructure/logging/src/main/java/tech/pegasys/teku/infrastructure/logging/DbLogger.java b/infrastructure/logging/src/main/java/tech/pegasys/teku/infrastructure/logging/DbLogger.java index a9204726d6f..d62aba4c335 100644 --- a/infrastructure/logging/src/main/java/tech/pegasys/teku/infrastructure/logging/DbLogger.java +++ b/infrastructure/logging/src/main/java/tech/pegasys/teku/infrastructure/logging/DbLogger.java @@ -15,6 +15,7 @@ import static tech.pegasys.teku.infrastructure.logging.ColorConsolePrinter.print; +import java.util.function.Supplier; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import tech.pegasys.teku.infrastructure.logging.ColorConsolePrinter.Color; @@ -33,14 +34,17 @@ public DbLogger(final String name) { } public void onDbOpAlertThreshold( - final String opName, final long startTimeMillis, final long endTimeMillis) { + final String opName, + final Supplier additionalInfo, + final long startTimeMillis, + final long endTimeMillis) { final long duration = endTimeMillis - startTimeMillis; if (dbOpAlertThresholdMillis > 0 && duration >= dbOpAlertThresholdMillis) { logger.warn( print( String.format( - "DB operation %s took too long: %d ms. The alert threshold is set to: %d ms", - opName, duration, dbOpAlertThresholdMillis), + "DB operation %s took too long: %d ms. The alert threshold is set to: %d ms. Additional info: %s", + opName, duration, dbOpAlertThresholdMillis, additionalInfo.get()), Color.YELLOW)); } } diff --git a/storage/src/main/java/tech/pegasys/teku/storage/server/kvstore/KvStoreDatabase.java b/storage/src/main/java/tech/pegasys/teku/storage/server/kvstore/KvStoreDatabase.java index ac57d966e79..ee98503859e 100644 --- a/storage/src/main/java/tech/pegasys/teku/storage/server/kvstore/KvStoreDatabase.java +++ b/storage/src/main/java/tech/pegasys/teku/storage/server/kvstore/KvStoreDatabase.java @@ -946,6 +946,7 @@ public void close() throws Exception { private UpdateResult doUpdate(final StorageUpdate update) { LOG.trace("Applying finalized updates"); + long startTime = System.currentTimeMillis(); // Update finalized blocks and states final Optional finalizedOptimisticExecutionPayload = updateFinalizedData( @@ -964,9 +965,11 @@ private UpdateResult doUpdate(final StorageUpdate update) { update.getEarliestBlobSidecarSlot(), update.getBlobSidecars().values().stream().flatMap(Collection::stream)); } + long finalizedDataUpdatedTime = System.currentTimeMillis(); LOG.trace("Applying hot updates"); - long startTime = System.currentTimeMillis(); + final long latestFinalizedStateUpdateStartTime; + final long latestFinalizedStateUpdateEndTime; try (final HotUpdater updater = hotUpdater()) { // Store new hot data update.getGenesisTime().ifPresent(updater::setGenesisTime); @@ -983,7 +986,9 @@ private UpdateResult doUpdate(final StorageUpdate update) { update.getJustifiedCheckpoint().ifPresent(updater::setJustifiedCheckpoint); update.getBestJustifiedCheckpoint().ifPresent(updater::setBestJustifiedCheckpoint); + latestFinalizedStateUpdateStartTime = System.currentTimeMillis(); update.getLatestFinalizedState().ifPresent(updater::setLatestFinalizedState); + latestFinalizedStateUpdateEndTime = System.currentTimeMillis(); updateHotBlocks(updater, update.getHotBlocks(), update.getDeletedHotBlocks().keySet()); updater.addHotStates(update.getHotStates()); @@ -999,7 +1004,16 @@ private UpdateResult doUpdate(final StorageUpdate update) { } long endTime = System.currentTimeMillis(); - DB_LOGGER.onDbOpAlertThreshold("KvStoreDatabase::doUpdate", startTime, endTime); + DB_LOGGER.onDbOpAlertThreshold( + "KvStoreDatabase::doUpdate", + () -> + String.format( + "Finalized data updated time: %d ms - Hot data updated time: %d ms of which latest finalized state updated time: %d ms", + finalizedDataUpdatedTime - startTime, + endTime - finalizedDataUpdatedTime, + latestFinalizedStateUpdateEndTime - latestFinalizedStateUpdateStartTime), + startTime, + endTime); LOG.trace("Update complete"); return new UpdateResult(finalizedOptimisticExecutionPayload); } diff --git a/storage/src/main/java/tech/pegasys/teku/storage/server/leveldb/LevelDbTransaction.java b/storage/src/main/java/tech/pegasys/teku/storage/server/leveldb/LevelDbTransaction.java index 46561eaf85a..1235aaac991 100644 --- a/storage/src/main/java/tech/pegasys/teku/storage/server/leveldb/LevelDbTransaction.java +++ b/storage/src/main/java/tech/pegasys/teku/storage/server/leveldb/LevelDbTransaction.java @@ -96,7 +96,8 @@ public void commit() { long startTime = System.currentTimeMillis(); db.write(writeBatch); long endTime = System.currentTimeMillis(); - DB_LOGGER.onDbOpAlertThreshold("LevelDbTransaction::commit", startTime, endTime); + DB_LOGGER.onDbOpAlertThreshold( + "LevelDbTransaction::commit", () -> "N/A", startTime, endTime); } finally { close(); }