add more block processing durations (#2611)

beacon_chain/consensus_object_pools/block_clearance.nim

@@ -78,7 +78,8 @@ proc addResolvedBlock(
        dag: var ChainDAGRef, quarantine: var QuarantineRef,
        state: var StateData, trustedBlock: TrustedSignedBeaconBlock,
        parent: BlockRef, cache: var StateCache,
-       onBlockAdded: OnBlockAdded
+       onBlockAdded: OnBlockAdded, stateDataDur, sigVerifyDur,
+       stateVerifyDur: Duration
      ) =
   # TODO move quarantine processing out of here
   doAssert getStateField(state, slot) == trustedBlock.message.slot,
@@ -108,7 +109,7 @@ proc addResolvedBlock(
 
   # Resolved blocks should be stored in database
   dag.putBlock(trustedBlock)
-  let putTick = Moment.now()
+  let putBlockTick = Moment.now()
 
   var foundHead: BlockRef
   for head in dag.heads.mitems():
@@ -127,8 +128,9 @@ proc addResolvedBlock(
     blck = shortLog(trustedBlock.message),
     blockRoot = shortLog(blockRoot),
     heads = dag.heads.len(),
+    stateDataDur, sigVerifyDur, stateVerifyDur,
     epochRefDur = epochRefTick - startTick,
-    putBlockDur = putTick - epochRefTick
+    putBlockDur = putBlockTick - epochRefTick
 
   state.blck = blockRef
 
@@ -221,13 +223,14 @@ proc addRawBlockKnownParent(
 
   # The block is resolved, now it's time to validate it to ensure that the
   # blocks we add to the database are clean for the given state
-
+  let startTick = Moment.now()
 
   # TODO if the block is from the future, we should not be resolving it (yet),
   #      but maybe we should use it as a hint that our clock is wrong?
   var cache = StateCache()
   updateStateData(
     dag, dag.clearanceState, parent.atSlot(signedBlock.message.slot), true, cache)
+  let stateDataTick = Moment.now()
 
   # First batch verify crypto
   if skipBLSValidation notin dag.updateFlags:
@@ -240,19 +243,23 @@ proc addRawBlockKnownParent(
     if not quarantine.batchVerify(sigs):
       return err((ValidationResult.Reject, Invalid))
 
+  let sigVerifyTick = Moment.now()
   static: doAssert sizeof(SignedBeaconBlock) == sizeof(SigVerifiedSignedBeaconBlock)
   let (valRes, blockErr) = addRawBlockCheckStateTransition(
     dag, quarantine, signedBlock.asSigVerified(), cache)
   if valRes != ValidationResult.Accept:
     return err((valRes, blockErr))
-
+  let stateVerifyTick = Moment.now()
   # Careful, clearanceState.data has been updated but not blck - we need to
   # create the BlockRef first!
   addResolvedBlock(
     dag, quarantine, dag.clearanceState,
     signedBlock.asTrusted(),
     parent, cache,
-    onBlockAdded)
+    onBlockAdded,
+    stateDataDur = stateDataTick - startTick,
+    sigVerifyDur = sigVerifyTick - stateDataTick,
+    stateVerifyDur = stateVerifyTick - sigVerifyTick)
 
   return ok dag.clearanceState.blck
 

beacon_chain/consensus_object_pools/blockchain_dag.nim

@@ -919,12 +919,10 @@ proc pruneBlocksDAG(dag: ChainDAGRef) =
 
     dag.heads.del(n)
 
-  let dagPruningDur = Moment.now() - startTick
-
   debug "Pruned the blockchain DAG",
     currentCandidateHeads = dag.heads.len,
     prunedHeads = hlen - dag.heads.len,
-    dagPruningDur
+    dagPruneDur = Moment.now() - startTick
 
 func needStateCachesAndForkChoicePruning*(dag: ChainDAGRef): bool =
   dag.lastPrunePoint != dag.finalizedHead
@@ -937,7 +935,7 @@ proc pruneStateCachesDAG*(dag: ChainDAGRef) =
   ## This updates the `dag.lastPrunePoint` variable
   doAssert dag.needStateCachesAndForkChoicePruning()
 
-  let startState = Moment.now()
+  let startTick = Moment.now()
   block: # Remove states, walking slot by slot
     # We remove all state checkpoints that come _before_ the current finalized
     # head, as we might frequently be asked to replay states from the
@@ -955,10 +953,8 @@ proc pruneStateCachesDAG*(dag: ChainDAGRef) =
       if cur.slot.epoch mod 32 != 0 and cur.slot != dag.tail.slot:
         dag.delState(cur)
       cur = cur.parentOrSlot
-  let stopState = Moment.now()
-  let durState = stopState - startState
+  let statePruneTick = Moment.now()
 
-  let startEpochRef = Moment.now()
   block: # Clean up old EpochRef instances
     # After finalization, we can clear up the epoch cache and save memory -
     # it will be recomputed if needed
@@ -966,14 +962,13 @@ proc pruneStateCachesDAG*(dag: ChainDAGRef) =
       if dag.epochRefs[i][1] != nil and
           dag.epochRefs[i][1].epoch < dag.finalizedHead.slot.epoch:
         dag.epochRefs[i] = (nil, nil)
-  let stopEpochRef = Moment.now()
-  let durEpochRef = stopEpochRef - startEpochRef
+  let epochRefPruneTick = Moment.now()
 
   dag.lastPrunePoint = dag.finalizedHead
 
   debug "Pruned the state checkpoints and DAG caches.",
-    statePruningDur = durState,
-    epochRefPruningDur = durEpochRef
+    statePruneDur = statePruneTick - startTick,
+    epochRefPruneDur = epochRefPruneTick - statePruneTick
 
 proc updateHead*(
       dag: ChainDAGRef,

beacon_chain/gossip_processing/block_processor.nim

@@ -185,7 +185,7 @@ proc processBlock(self: var BlockProcessor, entry: BlockEntry) =
   let
     startTick = Moment.now()
     res = self.storeBlock(entry.blck, wallSlot)
-    storeTick = Moment.now()
+    storeBlockTick = Moment.now()
 
   if res.isOk():
     # Eagerly update head in case the new block gets selected
@@ -194,8 +194,8 @@ proc processBlock(self: var BlockProcessor, entry: BlockEntry) =
     let
       updateHeadTick = Moment.now()
       queueDur = startTick - entry.queueTick
-      storeBlockDur = storeTick - startTick
-      updateHeadDur = updateHeadTick - storeTick
+      storeBlockDur = storeBlockTick - startTick
+      updateHeadDur = updateHeadTick - storeBlockTick
 
     beacon_store_block_duration_seconds.observe(storeBlockDur.toFloatSeconds())