Setting the append, process, ph creation times into the header

core/slice.go

@@ -40,7 +40,7 @@ const (
 	c_pEtxRetryThreshold              = 10 // Number of pEtxNotFound return on a dom block before asking for pEtx/Rollup from sub
 	c_currentStateComputeWindow       = 20 // Number of blocks around the current header the state generation is always done
 	c_inboundEtxCacheSize             = 10 // Number of inboundEtxs to keep in cache so that, we don't recompute it every time dom is processed
-
+	c_appendTimeCacheSize             = 1000
 )
 
 // Core will implement the following interface to enable dom-sub communication
@@ -96,6 +96,8 @@ type Slice struct {
 
 	bestPh   *types.WorkObject
 	bestPhMu sync.RWMutex
+
+	appendTimeCache *lru.Cache[common.Hash, time.Duration]
 }
 
 func NewSlice(db ethdb.Database, config *Config, txConfig *TxPoolConfig, txLookupLimit *uint64, isLocalBlock func(block *types.WorkObject) bool, chainConfig *params.ChainConfig, slicesRunning []common.Location, currentExpansionNumber uint8, genesisBlock *types.WorkObject, engine consensus.Engine, cacheConfig *CacheConfig, vmConfig vm.Config, genesis *Genesis, logger *log.Logger) (*Slice, error) {
@@ -132,6 +134,8 @@ func NewSlice(db ethdb.Database, config *Config, txConfig *TxPoolConfig, txLooku
 
 	sl.inboundEtxsCache, _ = lru.New[common.Hash, types.Transactions](c_inboundEtxCacheSize)
 
+	sl.appendTimeCache, _ = lru.New[common.Hash, time.Duration](c_appendTimeCacheSize)
+
 	sl.subInterface = make([]CoreBackend, common.MaxWidth)
 
 	if err := sl.init(); err != nil {
@@ -371,6 +375,10 @@ func (sl *Slice) Append(header *types.WorkObject, domTerminus common.Hash, domOr
 		"t10":  time10,
 	}).Info("Times during append")
 
+	// store the append time for the block
+	appendTime := time.Since(start)
+	sl.appendTimeCache.Add(block.Hash(), appendTime)
+
 	sl.logger.WithFields(log.Fields{
 		"t5_1": time5_1,
 		"t5_2": time5_2,
@@ -1045,6 +1053,7 @@ func (sl *Slice) MakeFullPendingHeader(primePendingHeader, regionPendingHeader,
 }
 
 func (sl *Slice) GeneratePendingHeader(block *types.WorkObject, fill bool, stopChan chan struct{}) (*types.WorkObject, error) {
+	start := time.Now()
 	// set the current header to this block
 	switch sl.NodeCtx() {
 	case common.PRIME_CTX:
@@ -1066,6 +1075,7 @@ func (sl *Slice) GeneratePendingHeader(block *types.WorkObject, fill bool, stopC
 			return nil, err
 		}
 	}
+	stateProcessTime := time.Since(start)
 	if sl.bestPh == nil {
 		return nil, errors.New("best ph is nil")
 	}
@@ -1077,11 +1087,24 @@ func (sl *Slice) GeneratePendingHeader(block *types.WorkObject, fill bool, stopC
 	if bestPhCopy != nil && bestPhCopy.ParentHash(sl.NodeCtx()) == block.Hash() {
 		return bestPhCopy, nil
 	}
+
+	phStart := time.Now()
 	pendingHeader, err := sl.miner.worker.GeneratePendingHeader(block, fill, stopChan)
 	if err != nil {
 		return nil, err
 	}
+	pendingHeaderCreationTime := time.Since(phStart)
+
 	if sl.NodeCtx() == common.ZONE_CTX {
+		// Set the block processing times before sending the block in chain head
+		// feed
+		appendTime, exists := sl.appendTimeCache.Peek(block.Hash())
+		if exists {
+			block.SetAppendTime(appendTime)
+		}
+		block.SetStateProcessTime(stateProcessTime)
+		block.SetPendingHeaderCreationTime(pendingHeaderCreationTime)
+
 		sl.hc.chainHeadFeed.Send(ChainHeadEvent{block})
 	}
 	return pendingHeader, nil

core/types/wo.go

@@ -27,7 +27,9 @@ type WorkObject struct {
 	tx       *Transaction
 
 	// caches
-	appendTime atomic.Value
+	appendTime                atomic.Value
+	stateProcessTime          atomic.Value
+	pendingHeaderCreationTime atomic.Value
 
 	// These fields are used to track
 	// inter-peer block relay.
@@ -118,6 +120,14 @@ func (wo *WorkObject) SetAppendTime(appendTime time.Duration) {
 	wo.appendTime.Store(appendTime)
 }
 
+func (wo *WorkObject) SetStateProcessTime(stateProcessTimes time.Duration) {
+	wo.stateProcessTime.Store(stateProcessTimes)
+}
+
+func (wo *WorkObject) SetPendingHeaderCreationTime(pendingHeaderCreationTime time.Duration) {
+	wo.pendingHeaderCreationTime.Store(pendingHeaderCreationTime)
+}
+
 ////////////////////////////////////////////////////////////
 /////////////////// Work Object Generic Getters ///////////////
 ////////////////////////////////////////////////////////////
@@ -133,6 +143,28 @@ func (wo *WorkObject) GetAppendTime() time.Duration {
 	return -1
 }
 
+// GetStateProcessTime returns the stateProcessTIme of the block
+// The stateProcessTime is computed on the first call and cached thereafter.
+func (wo *WorkObject) GetStateProcessTime() time.Duration {
+	if stateProcessTime := wo.stateProcessTime.Load(); stateProcessTime != nil {
+		if val, ok := stateProcessTime.(time.Duration); ok {
+			return val
+		}
+	}
+	return -1
+}
+
+// GetPendingHeaderCreationTime returns the pendingHeaderTime of the block
+// The pendingHeaderTime is computed on the first call and cached thereafter.
+func (wo *WorkObject) GetPendingHeaderCreationTime() time.Duration {
+	if pendingHeaderCreationTime := wo.appendTime.Load(); pendingHeaderCreationTime != nil {
+		if val, ok := pendingHeaderCreationTime.(time.Duration); ok {
+			return val
+		}
+	}
+	return -1
+}
+
 // Size returns the true RLP encoded storage size of the block, either by encoding
 // and returning it, or returning a previsouly cached value.
 func (wo *WorkObject) Size() common.StorageSize {

quaistats/quaistats.go

@@ -1023,9 +1023,11 @@ type blockDetailStats struct {
 
 // Everyone sends every block
 type blockAppendTime struct {
-	AppendTime  time.Duration `json:"appendTime"`
-	BlockNumber *big.Int      `json:"number"`
-	Chain       string        `json:"chain"`
+	AppendTime                time.Duration `json:"appendTime"`
+	StateProcessTime          time.Duration `json:"stateProcessTime"`
+	PendingHeaderCreationTime time.Duration `json:"pendingHeaderCreationTime"`
+	BlockNumber               *big.Int      `json:"number"`
+	Chain                     string        `json:"chain"`
 }
 
 type nodeStats struct {
@@ -1292,14 +1294,16 @@ func (s *Service) assembleBlockAppendTimeStats(block *types.WorkObject) *blockAp
 		return nil
 	}
 	appendTime := block.GetAppendTime()
-
-	s.backend.Logger().WithField("appendTime", appendTime.Microseconds()).Info("Raw Block Append Time")
+	stateProcessTime := block.GetStateProcessTime()
+	pendingHeaderCreationTime := block.GetPendingHeaderCreationTime()
 
 	// Assemble and return the block stats
 	return &blockAppendTime{
-		AppendTime:  appendTime,
-		BlockNumber: block.Number(s.backend.NodeCtx()),
-		Chain:       s.backend.NodeLocation().Name(),
+		AppendTime:                appendTime,
+		StateProcessTime:          stateProcessTime,
+		PendingHeaderCreationTime: pendingHeaderCreationTime,
+		BlockNumber:               block.Number(s.backend.NodeCtx()),
+		Chain:                     s.backend.NodeLocation().Name(),
 	}
 }