chore: optimize perf trace log

bnoieh · Oct 10, 2024 · 1107a12 · 1107a12
1 parent f2b3fb9
commit 1107a12
Show file tree

Hide file tree

Showing 8 changed files with 30 additions and 19 deletions.
diff --git a/beacon/engine/types.go b/beacon/engine/types.go
@@ -229,7 +229,7 @@ func decodeTransactions(enc [][]byte) ([]*types.Transaction, error) {
 func ExecutableDataToBlock(params ExecutableData, versionedHashes []common.Hash, beaconRoot *common.Hash) (*types.Block, error) {
 	start := time.Now()
 	txs, err := decodeTransactions(params.Transactions)
-	log.Info("perf-trace ExecutableDataToBlock decodeTransactions", "duration", time.Since(start), "hash", params.BlockHash, "len", len(txs))
+	log.Info("perf-trace ExecutableDataToBlock decodeTransactions", "duration", time.Since(start), "number", params.Number, "len", len(txs))
 	if err != nil {
 		return nil, err
 	}
@@ -285,7 +285,7 @@ func ExecutableDataToBlock(params ExecutableData, versionedHashes []common.Hash,
 		BlobGasUsed:      params.BlobGasUsed,
 		ParentBeaconRoot: beaconRoot,
 	}
-	log.Info("perf-trace ExecutableDataToBlock DeriveSha", "duration", time.Since(start), "hash", params.BlockHash, "len", len(txs))
+	log.Info("perf-trace ExecutableDataToBlock DeriveSha", "duration", time.Since(start), "hash", params.BlockHash, "number", params.Number, "len", len(txs))
 	block := types.NewBlockWithHeader(header).WithBody(txs, nil /* uncles */).WithWithdrawals(params.Withdrawals)
 	if block.Hash() != params.BlockHash {
 		return nil, fmt.Errorf("blockhash mismatch, want %x, got %x", params.BlockHash, block.Hash())

diff --git a/consensus/beacon/consensus.go b/consensus/beacon/consensus.go
@@ -405,7 +405,7 @@ func (beacon *Beacon) FinalizeAndAssemble(chain consensus.ChainHeaderReader, hea
 	go func() {
 		start := time.Now()
 		root := state.IntermediateRoot(true)
-		log.Info("perf-trace async FinalizeAndAssemble IntermediateRoot", "duration", time.Since(start), "hash", header.Hash())
+		log.Info("perf-trace async FinalizeAndAssemble IntermediateRoot", "duration", time.Since(start), "number", header.Number.Uint64())
 		rootCh <- root
 	}()
 

diff --git a/core/blockchain.go b/core/blockchain.go
@@ -1002,7 +1002,7 @@ func (bc *BlockChain) writeHeadBlock(block *types.Block) {
 	if err := batch.Write(); err != nil {
 		log.Crit("Failed to update chain indexes and markers", "err", err)
 	}
-	log.Info("perf-trace perf-db-trace SetCanonical writeHeadBlock", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
+	log.Info("perf-trace perf-db-trace SetCanonical writeHeadBlock", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash(), "number", block.NumberU64())
 	// Update all in-memory chain markers in the last step
 	bc.hc.SetCurrentHeader(block.Header())
 
@@ -1443,6 +1443,9 @@ func (bc *BlockChain) writeKnownBlock(block *types.Block) error {
 // writeBlockWithState writes block, metadata and corresponding state data to the
 // database.
 func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.Receipt, state *state.StateDB) error {
+	defer func(start time.Time) {
+		log.Info("perf-trace writeBlockWithState", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash(), "number", block.NumberU64())
+	}(time.Now())
 	// Calculate the total difficulty of the block
 	ptd := bc.GetTd(block.ParentHash(), block.NumberU64()-1)
 	if ptd == nil {
@@ -1473,7 +1476,7 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.
 			log.Crit("Failed to write block into disk", "err", err)
 		}
 		blockWriteExternalTimer.UpdateSince(start)
-		log.Info("perf-trace perf-db-trace writeBlockWithState writeBlock", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash(), "len", len(receipts))
+		log.Info("perf-trace perf-db-trace writeBlockWithState writeBlock", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash(), "number", block.NumberU64(), "len", len(receipts))
 	}()
 
 	// Commit all cached state changes into underlying memory database.
@@ -1484,7 +1487,7 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.
 		return err
 	}
 	stateCommitExternalTimer.UpdateSince(start)
-	log.Info("perf-trace writeBlockWithState stateCommit", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
+	log.Info("perf-trace writeBlockWithState stateCommit", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash(), "number", block.NumberU64())
 
 	// If node is running in path mode, skip explicit gc operation
 	// which is unnecessary in this mode.
@@ -1714,9 +1717,10 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 	var err error
 	traceStart := time.Now()
 	if !minerMode {
+		// TODO
 		block, err = it.next()
 	}
-	log.Info("perf-trace InsertChain it.next", "duration", common.PrettyDuration(time.Since(traceStart)), "hash", chain[0].Header().Hash())
+	log.Info("perf-trace InsertChain it.next", "duration", common.PrettyDuration(time.Since(traceStart)), "hash", chain[0].Header().Hash(), "number", chain[0].NumberU64())
 
 	// Left-trim all the known blocks that don't need to build snapshot
 	if bc.skipBlock(err, it) {
@@ -1957,7 +1961,7 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 
 		innerExecutionTimer.Update(PerfTraceEvmExecutionDuration)
 
-		log.Info("perf-trace insertChain after execution and validation", "hash", block.Hash(), "execution", common.PrettyDuration(ptime), "validation", common.PrettyDuration(vtime), "accountReads", common.PrettyDuration(statedb.AccountReads), "storageReads", common.PrettyDuration(statedb.StorageReads), "snapshotAccountReads", common.PrettyDuration(statedb.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(statedb.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(statedb.AccountUpdates), "storageUpdates", common.PrettyDuration(statedb.StorageUpdates), "accountHashes", common.PrettyDuration(statedb.AccountHashes), "storageHashes", common.PrettyDuration(statedb.StorageHashes), "updateStoragesRoot", statedb.UpdateStoragesRootTimer, "updateAccountRoot", statedb.UpdateAccountRootTimer)
+		log.Info("perf-trace insertChain after execution and validation", "hash", block.Hash(), "number", block.NumberU64(), "execution", common.PrettyDuration(ptime), "validation", common.PrettyDuration(vtime), "accountReads", common.PrettyDuration(statedb.AccountReads), "storageReads", common.PrettyDuration(statedb.StorageReads), "snapshotAccountReads", common.PrettyDuration(statedb.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(statedb.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(statedb.AccountUpdates), "storageUpdates", common.PrettyDuration(statedb.StorageUpdates), "accountHashes", common.PrettyDuration(statedb.AccountHashes), "storageHashes", common.PrettyDuration(statedb.StorageHashes), "updateStoragesRoot", statedb.UpdateStoragesRootTimer, "updateAccountRoot", statedb.UpdateAccountRootTimer)
 
 		// Write the block to the chain and get the status.
 		var (
@@ -1967,20 +1971,26 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		if !setHead {
 			// Don't set the head, only insert the block
 			err = bc.writeBlockWithState(block, receipts, statedb)
+			log.Info("perf-trace insertChain debug0", "duration", common.PrettyDuration(time.Since(wstart)), "hash", block.Hash(), "number", block.NumberU64())
 		} else {
 			status, err = bc.writeBlockAndSetHead(block, receipts, logs, statedb, false)
 		}
 		followupInterrupt.Store(true)
+		log.Info("perf-trace insertChain debug1", "duration", common.PrettyDuration(time.Since(wstart)), "hash", block.Hash())
+
 		if err != nil {
 			return it.index, err
 		}
 		bc.CacheBlock(block.Hash(), block)
+		log.Info("perf-trace insertChain debug2", "duration", common.PrettyDuration(time.Since(wstart)), "hash", block.Hash())
 
 		// Update the metrics touched during block commit
 		accountCommitTimer.Update(statedb.AccountCommits)   // Account commits are complete, we can mark them
 		storageCommitTimer.Update(statedb.StorageCommits)   // Storage commits are complete, we can mark them
 		snapshotCommitTimer.Update(statedb.SnapshotCommits) // Snapshot commits are complete, we can mark them
 		triedbCommitTimer.Update(statedb.TrieDBCommits)     // Trie database commits are complete, we can mark them
+		log.Info("perf-trace insertChain debug3", "duration", common.PrettyDuration(time.Since(wstart)), "hash", block.Hash())
+
 		trieCommitTimer.Update(statedb.TrieCommits)
 		codeCommitTimer.Update(statedb.CodeCommits)
 
@@ -2264,7 +2274,7 @@ func (bc *BlockChain) collectLogs(b *types.Block, removed bool) []*types.Log {
 			logs = append(logs, log)
 		}
 	}
-	log.Info("perf-trace setCanonical collectLogs", "duration", time.Since(start), "hash", b.Hash())
+	log.Info("perf-trace setCanonical collectLogs", "duration", time.Since(start), "hash", b.Hash(), "number", b.NumberU64())
 	return logs
 }
 

diff --git a/core/state/statedb.go b/core/state/statedb.go
@@ -1311,7 +1311,7 @@ func (s *StateDB) Commit(block uint64, deleteEmptyObjects bool) (common.Hash, er
 
 	if metrics.EnabledExpensive {
 		defer func(start time.Time) {
-			s.AccountCommits += time.Since(start)
+			// s.AccountCommits += time.Since(start)
 			accountUpdatedMeter.Mark(int64(s.AccountUpdated))
 			storageUpdatedMeter.Mark(int64(s.StorageUpdated))
 			accountDeletedMeter.Mark(int64(s.AccountDeleted))

diff --git a/core/types/block.go b/core/types/block.go
@@ -250,7 +250,7 @@ func NewBlock(header *Header, txs []*Transaction, uncles []*Header, receipts []*
 			b.uncles[i] = CopyHeader(uncles[i])
 		}
 	}
-	log.Info("perf-trace assembleAndFinalise NewBlock", "duration", time.Since(start))
+	log.Info("perf-trace assembleAndFinalise NewBlock", "duration", time.Since(start), "number", header.Number.Uint64())
 
 	return b
 }

diff --git a/eth/catalyst/api.go b/eth/catalyst/api.go
@@ -590,7 +590,7 @@ func (api *ConsensusAPI) newPayload(params engine.ExecutableData, versionedHashe
 	start := time.Now()
 	defer func() {
 		newPayloadTimer.UpdateSince(start)
-		log.Info("perf-trace newPayload", "duration", common.PrettyDuration(time.Since(start)), "hash", params.BlockHash, "parentHash", params.ParentHash)
+		log.Info("perf-trace newPayload", "duration", common.PrettyDuration(time.Since(start)), "hash", params.BlockHash, "number", params.Number)
 	}()
 
 	// The locking here is, strictly, not required. Without these locks, this can happen:
@@ -620,7 +620,7 @@ func (api *ConsensusAPI) newPayload(params engine.ExecutableData, versionedHashe
 			return api.invalid(err, nil), nil
 		}
 	}
-	log.Info("perf-trace newPayload ExecutableDataToBlock", "duration", common.PrettyDuration(time.Since(start)), "hash", params.BlockHash, "parentHash", params.ParentHash)
+	log.Info("perf-trace newPayload ExecutableDataToBlock", "duration", common.PrettyDuration(time.Since(start)), "hash", params.BlockHash, "number", params.Number)
 
 	// Stash away the last update to warn the user if the beacon client goes offline
 	api.lastNewPayloadLock.Lock()
@@ -696,7 +696,7 @@ func (api *ConsensusAPI) newPayload(params engine.ExecutableData, versionedHashe
 
 		return api.invalid(err, parent.Header()), nil
 	}
-	log.Info("perf-trace newPayload InsertBlockWithoutSetHead", "duration", common.PrettyDuration(time.Since(start1)), "hash", params.BlockHash, "parentHash", params.ParentHash)
+	log.Info("perf-trace newPayload InsertBlockWithoutSetHead", "duration", common.PrettyDuration(time.Since(start1)), "hash", params.BlockHash, "number", params.Number)
 	// We've accepted a valid payload from the beacon client. Mark the local
 	// chain transitions to notify other subsystems (e.g. downloader) of the
 	// behavioral change.
@@ -737,7 +737,7 @@ func (api *ConsensusAPI) opSealPayload(payloadID engine.PayloadID, update engine
 	}
 
 	log.Info("Seal payload succeed", "payloadStatus", updateResponse.PayloadStatus)
-	log.Info("perf-trace opSealPayload", "duration", common.PrettyDuration(time.Since(start)), "hash", payloadEnvelope.ExecutionPayload.BlockHash, "number", payloadEnvelope.ExecutionPayload.Number)
+	log.Info("perf-trace opSealPayload", "duration", common.PrettyDuration(time.Since(start)), "hash", payloadEnvelope.ExecutionPayload.BlockHash, "number", payloadEnvelope.ExecutionPayload.Number, "id", payloadID)
 	return engine.OpSealPayloadResponse{PayloadStatus: updateResponse.PayloadStatus, Payload: payloadEnvelope}, nil
 }
 

diff --git a/eth/catalyst/queue.go b/eth/catalyst/queue.go
@@ -135,6 +135,7 @@ func (q *payloadQueue) getBlockByHash(hash common.Hash) *types.Block {
 		if item == nil {
 			return nil
 		}
+		// TODO
 		block := item.payload.GetBlock()
 		if block.Hash() == hash {
 			return block

diff --git a/miner/worker.go b/miner/worker.go
@@ -911,7 +911,7 @@ func (w *worker) commitTransactions(env *environment, plainTxs, blobTxs *transac
 	commitTxTimer := time.Duration(0)
 	shiftTxTimer := time.Duration(0)
 	defer func() {
-		log.Info("perf-trace commitTransactions", "duration", time.Since(start), "hash", env.header.Hash(), "commitTx", commitTxTimer, "shiftTx", shiftTxTimer, "validateTx", env.tcount, "nonceTooLowTx", nonceTooLowTxCount)
+		log.Info("perf-trace commitTransactions", "duration", time.Since(start), "number", env.header.Number.Uint64(), "commitTx", commitTxTimer, "shiftTx", shiftTxTimer, "validateTx", env.tcount, "nonceTooLowTx", nonceTooLowTxCount)
 	}()
 
 	for {
@@ -954,7 +954,7 @@ func (w *worker) commitTransactions(env *environment, plainTxs, blobTxs *transac
 			}
 		}
 		if ltx == nil {
-			log.Info("perf-trace commitTransactions txpoolEmpty", "hash", env.header.Hash(), "count", env.tcount)
+			log.Info("perf-trace commitTransactions txpoolEmpty", "number", env.header.Number.Uint64(), "count", env.tcount)
 			break
 		}
 		txTotalMeter.Mark(1)
@@ -1213,7 +1213,7 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 	pendingBlobTxs := w.eth.TxPool().Pending(filter)
 
 	packFromTxpoolTimer.UpdateSince(start)
-	log.Info("perf-trace fillTransactions packFromPool", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash(), "txs", len(pendingPlainTxs))
+	log.Info("perf-trace fillTransactions packFromPool", "duration", common.PrettyDuration(time.Since(start)), "number", env.header.Number.Uint64(), "txs", len(pendingPlainTxs))
 
 	// Split the pending transactions into locals and remotes.
 	localPlainTxs, remotePlainTxs := make(map[common.Address][]*txpool.LazyTransaction), pendingPlainTxs
@@ -1242,7 +1242,7 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 	if len(remotePlainTxs) > 0 || len(remoteBlobTxs) > 0 {
 		plainTxs := newTransactionsByPriceAndNonce(env.signer, remotePlainTxs, env.header.BaseFee)
 		blobTxs := newTransactionsByPriceAndNonce(env.signer, remoteBlobTxs, env.header.BaseFee)
-		log.Info("perf-trace fillTransactions newTransactionsByPriceAndNonce", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash())
+		log.Info("perf-trace fillTransactions newTransactionsByPriceAndNonce", "duration", common.PrettyDuration(time.Since(start)), "number", env.header.Number.Uint64())
 		if err := w.commitTransactions(env, plainTxs, blobTxs, interrupt); err != nil {
 			return err
 		}