diff --git a/beacon-chain/blockchain/log.go b/beacon-chain/blockchain/log.go index 8c693b08e..b5f79f3a3 100644 --- a/beacon-chain/blockchain/log.go +++ b/beacon-chain/blockchain/log.go @@ -73,7 +73,7 @@ func logStateTransitionData(b interfaces.ReadOnlyBeaconBlock) error { return nil } -func logBlockSyncStatus(block interfaces.ReadOnlyBeaconBlock, blockRoot [32]byte, justified, finalized *ethpb.Checkpoint, receivedTime time.Time, genesisTime uint64) error { +func logBlockSyncStatus(block interfaces.ReadOnlyBeaconBlock, blockRoot [32]byte, justified, finalized *ethpb.Checkpoint, receivedTime time.Time, genesisTime uint64, daWaitedTime time.Duration) error { startTime, err := slots.ToTime(genesisTime, block.Slot()) if err != nil { return err @@ -93,7 +93,7 @@ func logBlockSyncStatus(block interfaces.ReadOnlyBeaconBlock, blockRoot [32]byte "parentRoot": fmt.Sprintf("0x%s...", hex.EncodeToString(parentRoot[:])[:8]), "version": version.String(block.Version()), "sinceSlotStartTime": prysmTime.Now().Sub(startTime), - "chainServiceProcessedTime": prysmTime.Now().Sub(receivedTime), + "chainServiceProcessedTime": prysmTime.Now().Sub(receivedTime) - daWaitedTime, "deposits": len(block.Body().Deposits()), } log.WithFields(lf).Debug("Synced new block") diff --git a/beacon-chain/blockchain/receive_block.go b/beacon-chain/blockchain/receive_block.go index 8f1162b8a..7e2c494c7 100644 --- a/beacon-chain/blockchain/receive_block.go +++ b/beacon-chain/blockchain/receive_block.go @@ -106,9 +106,13 @@ func (s *Service) ReceiveBlock(ctx context.Context, block interfaces.ReadOnlySig if err := eg.Wait(); err != nil { return err } + + daStartTime := time.Now() if err := s.isDataAvailable(ctx, blockRoot, blockCopy); err != nil { return errors.Wrap(err, "could not validate blob data availability") } + daWaitedTime := time.Since(daStartTime) + // The rest of block processing takes a lock on forkchoice. s.cfg.ForkChoiceStore.Lock() defer s.cfg.ForkChoiceStore.Unlock() @@ -171,7 +175,7 @@ func (s *Service) ReceiveBlock(ctx context.Context, block interfaces.ReadOnlySig // Log block sync status. cp = s.cfg.ForkChoiceStore.JustifiedCheckpoint() justified := ðpb.Checkpoint{Epoch: cp.Epoch, Root: bytesutil.SafeCopyBytes(cp.Root[:])} - if err := logBlockSyncStatus(blockCopy.Block(), blockRoot, justified, finalized, receivedTime, uint64(s.genesisTime.Unix())); err != nil { + if err := logBlockSyncStatus(blockCopy.Block(), blockRoot, justified, finalized, receivedTime, uint64(s.genesisTime.Unix()), daWaitedTime); err != nil { log.WithError(err).Error("Unable to log block sync status") } // Log payload data @@ -183,7 +187,8 @@ func (s *Service) ReceiveBlock(ctx context.Context, block interfaces.ReadOnlySig log.WithError(err).Error("Unable to log state transition data") } - chainServiceProcessingTime.Observe(float64(time.Since(receivedTime).Milliseconds())) + timeWithoutDaWait := time.Since(receivedTime) - daWaitedTime + chainServiceProcessingTime.Observe(float64(timeWithoutDaWait.Milliseconds())) return nil }