Merge remote-tracking branch 'origin/simplify_loading_freeing_trusted…

…_setup'
StefanBratanov · Oct 23, 2023 · db24e04 · db24e04
2 parents 4b530df + 5295305
commit db24e04
Show file tree

Hide file tree

Showing 3 changed files with 25 additions and 6 deletions.
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
@@ -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<String> 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
@@ -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<SlotAndExecutionPayloadSummary> 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
@@ -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();
           }