Show mev and extra data in block logs

src/Nethermind/Nethermind.Consensus/Processing/BlockchainProcessor.cs

@@ -419,7 +419,21 @@ private void FireProcessingQueueEmpty()
             Metrics.LastBlockProcessingTimeInMs = blockProcessingTimeInMicrosecs / 1000;
             Metrics.RecoveryQueueSize = _recoveryQueue.Count;
             Metrics.ProcessingQueueSize = _blockQueue.Count;
-            _stats.UpdateStats(lastProcessed, blockProcessingTimeInMicrosecs);
+
+            Transaction[] txs = suggestedBlock.Transactions;
+            Address beneficiary = suggestedBlock.Header.GasBeneficiary;
+            Transaction lastTx = txs.Length > 0 ? txs[^1] : null;
+            bool isMev = false;
+            if (lastTx is not null && (lastTx.SenderAddress == beneficiary || _alternateMevPayees.Contains(lastTx.SenderAddress)))
+            {
+                // Mev reward with in last tx
+                beneficiary = lastTx.To;
+                isMev = true;
+            }
+            UInt256 beforeBalance = _stateReader.GetBalance(processingBranch.Root, beneficiary);
+            UInt256 afterBalance = _stateReader.GetBalance(suggestedBlock.StateRoot, beneficiary);
+            UInt256 rewards = beforeBalance < afterBalance ? afterBalance - beforeBalance : default;
+            _stats.UpdateStats(lastProcessed, blockProcessingTimeInMicrosecs, rewards, isMev);
         }
 
         bool updateHead = !options.ContainsFlag(ProcessingOptions.DoNotUpdateHead);
@@ -770,6 +784,13 @@ public void Dispose()
         _blockTree.NewHeadBlock -= OnNewHeadBlock;
     }
 
+    // Help identify mev blocks when doesn't follow regular pattern
+    private static HashSet<AddressAsKey> _alternateMevPayees = new()
+    {
+        new Address("0xa83114A443dA1CecEFC50368531cACE9F37fCCcb"), // Extra data as: beaverbuild.org
+        new Address("0x9FC3da866e7DF3a1c57adE1a97c9f00a70f010c8"), // Extra data as: Titan (titanbuilder.xyz)
+    };
+
     [DebuggerDisplay("Root: {Root}, Length: {BlocksToProcess.Count}")]
     private readonly struct ProcessingBranch
     {

src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs

@@ -16,7 +16,6 @@ namespace Nethermind.Consensus.Processing
     internal class ProcessingStats : IThreadPoolWorkItem
     {
         private readonly ILogger _logger;
-        private readonly Stopwatch _processingStopwatch = new();
         private readonly Stopwatch _runStopwatch = new();
         private long _lastBlockNumber;
         private long _lastElapsedRunningMicroseconds;
@@ -27,13 +26,11 @@ internal class ProcessingStats : IThreadPoolWorkItem
         private long _lastTotalSLoad;
         private long _lastTotalSStore;
         private long _lastSelfDestructs;
-        private long _totalBlocks;
         private long _chunkProcessingMicroseconds;
         private long _lastTotalCreates;
         private long _lastReportMs;
-        private long _lastContractsAnalysed;
+        private long _lastContractsAnalyzed;
         private long _lastCachedContractsUsed;
-        private long _blockProcessingMicroseconds;
         private long _runningMicroseconds;
         private long _runMicroseconds;
         private long _reportMs;
@@ -45,6 +42,8 @@ internal class ProcessingStats : IThreadPoolWorkItem
         private long _codeDbCacheProcessing;
         private long _contractAnalysedProcessing;
         private long _createsProcessing;
+        private UInt256 _rewards;
+        private bool _isMev;
 
         public ProcessingStats(ILogger logger)
         {
@@ -57,14 +56,9 @@ public ProcessingStats(ILogger logger)
 #endif
         }
 
-        public void UpdateStats(Block? block, long blockProcessingTimeInMicros)
+        public void UpdateStats(Block? block, long blockProcessingTimeInMicros, in UInt256 rewards, bool isMev)
         {
-            if (block is null)
-            {
-                return;
-            }
-
-            _processingStopwatch.Stop();
+            if (block is null) return;
 
             if (_lastBlockNumber == 0)
             {
@@ -83,7 +77,6 @@ public void UpdateStats(Block? block, long blockProcessingTimeInMicros)
 
             Metrics.BlockchainHeight = block.Header.Number;
 
-            _blockProcessingMicroseconds = _processingStopwatch.ElapsedMicroseconds();
             _runningMicroseconds = _runStopwatch.ElapsedMicroseconds();
             _runMicroseconds = (_runningMicroseconds - _lastElapsedRunningMicroseconds);
 
@@ -99,6 +92,8 @@ public void UpdateStats(Block? block, long blockProcessingTimeInMicros)
                 _codeDbCacheProcessing = Db.Metrics.ThreadLocalCodeDbCache;
                 _contractAnalysedProcessing = Evm.Metrics.ThreadLocalContractsAnalysed;
                 _createsProcessing = Evm.Metrics.ThreadLocalCreates;
+                _rewards = rewards;
+                _isMev = isMev;
                 GenerateReport();
             }
         }
@@ -107,6 +102,7 @@ public void UpdateStats(Block? block, long blockProcessingTimeInMicros)
 
         void IThreadPoolWorkItem.Execute()
         {
+            const long weiToEth = 1_000_000_000_000_000_000;
             const string resetColor = "\u001b[37m";
             const string whiteText = "\u001b[97m";
             const string yellowText = "\u001b[93m";
@@ -118,10 +114,12 @@ void IThreadPoolWorkItem.Execute()
             const string blueText = "\u001b[94m";
             const string darkGreyText = resetColor; // "\u001b[90m";
 
+            Block? block = Interlocked.Exchange(ref _lastBlock, null);
+            if (block is null) return;
+
             long currentSelfDestructs = Evm.Metrics.SelfDestructs;
 
             long chunkBlocks = Metrics.Blocks - _lastBlockNumber;
-            _totalBlocks += chunkBlocks;
 
             double chunkMicroseconds = _chunkProcessingMicroseconds;
             double chunkMGas = Metrics.Mgas - _lastTotalMGas;
@@ -140,21 +138,16 @@ void IThreadPoolWorkItem.Execute()
                 }
             }
 
-            Block? block = Interlocked.Exchange(ref _lastBlock, null);
-            if (block is not null && _logger.IsInfo)
+            if (_logger.IsInfo)
             {
-                double totalMicroseconds = _blockProcessingMicroseconds;
                 long chunkTx = Metrics.Transactions - _lastTotalTx;
                 long chunkCalls = _callsProcessing - _lastTotalCalls;
                 long chunkEmptyCalls = _emptyCallsProcessing - _lastTotalEmptyCalls;
                 long chunkCreates = _createsProcessing - _lastTotalCreates;
                 long chunkSload = _sloadOpcodeProcessing - _lastTotalSLoad;
                 long chunkSstore = _sstoreOpcodeProcessing - _lastTotalSStore;
-                long contractsAnalysed = _contractAnalysedProcessing - _lastContractsAnalysed;
+                long contractsAnalysed = _contractAnalysedProcessing - _lastContractsAnalyzed;
                 long cachedContractsUsed = _codeDbCacheProcessing - _lastCachedContractsUsed;
-                double totalMgasPerSecond = totalMicroseconds == 0 ? -1 : Metrics.Mgas / totalMicroseconds * 1_000_000.0;
-                double totalTxPerSecond = totalMicroseconds == 0 ? -1 : Metrics.Transactions / totalMicroseconds * 1_000_000.0;
-                double totalBlocksPerSecond = totalMicroseconds == 0 ? -1 : _totalBlocks / totalMicroseconds * 1_000_000.0;
                 double txps = chunkMicroseconds == 0 ? -1 : chunkTx / chunkMicroseconds * 1_000_000.0;
                 double bps = chunkMicroseconds == 0 ? -1 : chunkBlocks / chunkMicroseconds * 1_000_000.0;
                 double chunkMs = (chunkMicroseconds == 0 ? -1 : chunkMicroseconds / 1000.0);
@@ -235,7 +228,7 @@ void IThreadPoolWorkItem.Execute()
                 var recoveryQueue = Metrics.RecoveryQueueSize;
                 var processingQueue = Metrics.ProcessingQueueSize;
 
-                _logger.Info($"- Block{(chunkBlocks > 1 ? $"s {chunkBlocks,-9:N0}" : "           ")}{(chunkBlocks == 1 ? mgasColor : "")} {chunkMGas,9:F2}{resetColor} MGas    | {chunkTx,8:N0}   txs |  calls {callsColor}{chunkCalls,6:N0}{resetColor} {darkGreyText}({chunkEmptyCalls,3:N0}){resetColor} | sload {chunkSload,7:N0} | sstore {sstoreColor}{chunkSstore,6:N0}{resetColor} | create {createsColor}{chunkCreates,3:N0}{resetColor}{(currentSelfDestructs - _lastSelfDestructs > 0 ? $"{darkGreyText}({-(currentSelfDestructs - _lastSelfDestructs),3:N0}){resetColor}" : "")}");
+                _logger.Info($"- Block{(chunkBlocks > 1 ? $"s {chunkBlocks,-9:N0}  " : $"{(_isMev ? " mev" : "    ")} {_rewards.ToDecimal(null) / weiToEth,5:N3}Eth")}{(chunkBlocks == 1 ? mgasColor : "")} {chunkMGas,7:F2}{resetColor} MGas    | {chunkTx,8:N0}   txs |  calls {callsColor}{chunkCalls,6:N0}{resetColor} {darkGreyText}({chunkEmptyCalls,3:N0}){resetColor} | sload {chunkSload,7:N0} | sstore {sstoreColor}{chunkSstore,6:N0}{resetColor} | create {createsColor}{chunkCreates,3:N0}{resetColor}{(currentSelfDestructs - _lastSelfDestructs > 0 ? $"{darkGreyText}({-(currentSelfDestructs - _lastSelfDestructs),3:N0}){resetColor}" : "")}");
                 if (recoveryQueue > 0 || processingQueue > 0)
                 {
                     _logger.Info($"- Block throughput {mgasPerSecondColor}{mgasPerSecond,9:F2}{resetColor} MGas/s{(mgasPerSecond > 1000 ? "🔥" : "  ")}| {txps,10:N1} tps |       {bps,7:F2} Blk/s | recover {recoveryQueue,5:N0} | process {processingQueue,5:N0}");
@@ -244,16 +237,10 @@ void IThreadPoolWorkItem.Execute()
                 {
                     _logger.Info($"- Block throughput {mgasPerSecondColor}{mgasPerSecond,9:F2}{resetColor} MGas/s{(mgasPerSecond > 1000 ? "🔥" : "  ")}| {txps,10:N1} tps |       {bps,7:F2} Blk/s | exec code {resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} new {contractsAnalysed,6:N0}");
                 }
-
-                // Only output the total throughput in debug mode
-                if (_logger.IsDebug)
-                {
-                    _logger.Debug($"- Total throughput {totalMgasPerSecond,9:F2} MGas/s  | {totalTxPerSecond,9:F2} tps |       {totalBlocksPerSecond,7:F2} Blk/s |⛽ Gas gwei: {Evm.Metrics.MinGasPrice:N2} .. {Math.Max(Evm.Metrics.MinGasPrice, Evm.Metrics.EstMedianGasPrice):N2} ({Evm.Metrics.AveGasPrice:N2}) .. {Evm.Metrics.MaxGasPrice:N2}");
-                }
             }
 
             _lastCachedContractsUsed = _codeDbCacheProcessing;
-            _lastContractsAnalysed = _contractAnalysedProcessing;
+            _lastContractsAnalyzed = _contractAnalysedProcessing;
             _lastBlockNumber = Metrics.Blocks;
             _lastTotalMGas = Metrics.Mgas;
             _lastElapsedRunningMicroseconds = _runningMicroseconds;
@@ -269,7 +256,6 @@ void IThreadPoolWorkItem.Execute()
 
         public void Start()
         {
-            _processingStopwatch.Start();
             if (!_runStopwatch.IsRunning)
             {
                 _lastReportMs = Environment.TickCount64;

src/Nethermind/Nethermind.Merge.Plugin/Handlers/ForkchoiceUpdatedHandler.cs

@@ -2,8 +2,10 @@
 // SPDX-License-Identifier: LGPL-3.0-only
 
 using System;
+using System.Buffers;
 using System.Collections.Generic;
 using System.Diagnostics.CodeAnalysis;
+using System.Text;
 using System.Threading;
 using System.Threading.Tasks;
 using Nethermind.Blockchain;
@@ -13,6 +15,7 @@
 using Nethermind.Consensus.Producers;
 using Nethermind.Core;
 using Nethermind.Core.Crypto;
+using Nethermind.Core.Extensions;
 using Nethermind.Core.Specs;
 using Nethermind.Core.Threading;
 using Nethermind.Crypto;
@@ -51,6 +54,7 @@ public class ForkchoiceUpdatedHandler : IForkchoiceUpdatedHandler
     private readonly bool _simulateBlockProduction;
     private readonly ulong _secondsPerSlot;
     private readonly ISyncPeerPool _syncPeerPool;
+    private readonly bool _showExtraData;
 
     public ForkchoiceUpdatedHandler(
         IBlockTree blockTree,
@@ -67,7 +71,8 @@ public ForkchoiceUpdatedHandler(
         ISyncPeerPool syncPeerPool,
         ILogManager logManager,
         ulong secondsPerSlot,
-        bool simulateBlockProduction = false)
+        bool simulateBlockProduction = false,
+        bool showExtraData = true)
     {
         _blockTree = blockTree ?? throw new ArgumentNullException(nameof(blockTree));
         _manualBlockFinalizationManager = manualBlockFinalizationManager ?? throw new ArgumentNullException(nameof(manualBlockFinalizationManager));
@@ -84,6 +89,7 @@ public ForkchoiceUpdatedHandler(
         _simulateBlockProduction = simulateBlockProduction;
         _secondsPerSlot = secondsPerSlot;
         _logger = logManager.GetClassLogger();
+        _showExtraData = showExtraData;
     }
 
     public async Task<ResultWrapper<ForkchoiceUpdatedV1Result>> Handle(ForkchoiceStateV1 forkchoiceState, PayloadAttributes? payloadAttributes, int version)
@@ -279,12 +285,118 @@ protected virtual bool IsNewHeadAlignedWithChain(Block newHeadBlock, ForkchoiceS
         if (shouldUpdateHead)
         {
             _poSSwitcher.ForkchoiceUpdated(newHeadBlock.Header, forkchoiceState.FinalizedBlockHash);
-            if (_logger.IsInfo) _logger.Info($"Synced Chain Head to {newHeadBlock.ToString(Block.Format.Short)}");
+            if (_logger.IsInfo) _logger.Info($"Synced Chain Head to {newHeadBlock.ToString(Block.Format.Short)}{ParseExtraData(newHeadBlock.Header.ExtraData, newHeadBlock.Header.GasBeneficiary)}");
         }
 
         return null;
     }
 
+    private string ParseExtraData(byte[] data, Address? gasBeneficiary)
+    {
+        if (!_showExtraData) return string.Empty;
+
+        if (data is null || data.Length == 0)
+        {
+            // If no extra data just show GasBeneficiary address
+            return $", Address: {(gasBeneficiary?.ToString() ?? "0x")}";
+        }
+
+        // Ideally we'd prefer to show text; so convert invalid unicode
+        // and control chars to spaces and trim leading and trailing spaces.
+        string extraData = CleanUtf8ByteArray(data);
+
+        // If the cleaned text is less than half length of input size,
+        // output it as hex, else output the text.
+        return extraData.Length > data.Length / 2 ?
+            $", Extra Data: {extraData}" :
+            $", Hex: {data.ToHexString(withZeroX: true)}";
+    }
+
+    public static string CleanUtf8ByteArray(byte[] bytes)
+    {
+        // The maximum number of UTF-16 chars is bytes.Length, but each Rune can be up to 2 chars.
+        // So we allocate bytes.Length to bytes.Length * 2 chars.
+        const int maxOutputChars = 32 * 2;
+
+        if (bytes == null || bytes.Length == 0 || bytes.Length > 32)
+            return string.Empty;
+
+        // Allocate a char buffer on the stack.
+        Span<char> outputBuffer = stackalloc char[maxOutputChars];
+
+        int outputPos = 0;
+        int index = 0;
+        bool hasValidContent = false;
+        bool shouldAddSpace = false;
+
+        while (index < bytes.Length)
+        {
+            ReadOnlySpan<byte> span = bytes.AsSpan(index);
+
+            OperationStatus status = Rune.DecodeFromUtf8(span, out Rune rune, out var bytesConsumed);
+            if (status == OperationStatus.Done)
+            {
+                if (!IsControlCharacter(rune))
+                {
+                    if (shouldAddSpace)
+                    {
+                        outputBuffer[outputPos++] = ' ';
+                        shouldAddSpace = false;
+                    }
+
+                    int charsNeeded = rune.Utf16SequenceLength;
+                    if (outputPos + charsNeeded > outputBuffer.Length)
+                    {
+                        // Expand output buffer
+                        int newSize = outputBuffer.Length * 2;
+                        char[] newBuffer = new char[newSize];
+                        outputBuffer.Slice(0, outputPos).CopyTo(newBuffer);
+                        outputBuffer = newBuffer;
+                    }
+
+                    rune.EncodeToUtf16(outputBuffer.Slice(outputPos));
+                    outputPos += charsNeeded;
+                    hasValidContent = true;
+                }
+                else
+                {
+                    // Control character encountered; set flag to add space if needed
+                    if (hasValidContent)
+                        shouldAddSpace = true;
+                }
+                index += bytesConsumed;
+            }
+            else if (status == OperationStatus.InvalidData)
+            {
+                // Invalid data; set flag to add space if needed
+                if (hasValidContent)
+                    shouldAddSpace = true;
+                index++;
+            }
+            else if (status == OperationStatus.NeedMoreData)
+            {
+                // Incomplete sequence at the end; break out of the loop
+                break;
+            }
+            else
+            {
+                // Unexpected status; treat as invalid data
+                if (hasValidContent)
+                    shouldAddSpace = true;
+                index++;
+            }
+        }
+
+        // Create the final string from the output buffer.
+        return outputPos > 0 ? new string(outputBuffer[..outputPos]) : string.Empty;
+    }
+
+    private static bool IsControlCharacter(Rune rune)
+    {
+        // Control characters are U+0000 to U+001F and U+007F to U+009F
+        return rune.Value <= 0x001F || (rune.Value >= 0x007F && rune.Value <= 0x009F);
+    }
+
     protected virtual bool IsPayloadAttributesTimestampValid(Block newHeadBlock, ForkchoiceStateV1 forkchoiceState, PayloadAttributes payloadAttributes,
         [NotNullWhen(false)] out ResultWrapper<ForkchoiceUpdatedV1Result>? errorResult)
     {

src/Nethermind/Nethermind.Merge.Plugin/IMergeConfig.cs

@@ -69,4 +69,7 @@ The number of requests to the garbage collector (GC) to release the process memo
 
     [ConfigItem(Description = "[TECHNICAL] Simulate block production for every possible slot. Just for stress-testing purposes.", DefaultValue = "false", HiddenFromDocs = true)]
     bool SimulateBlockProduction { get; set; }
+
+    [ConfigItem(Description = "Whether to show the block's Extra Data field in logs", DefaultValue = "true")]
+    bool ShowExtraData { get; set; }
 }

src/Nethermind/Nethermind.Merge.Plugin/MergeConfig.cs

@@ -34,5 +34,7 @@ public class MergeConfig : IMergeConfig
         public int NewPayloadTimeout { get; set; } = 7;
 
         public bool SimulateBlockProduction { get; set; } = false;
+
+        public bool ShowExtraData { get; set; } = true;
     }
 }

src/Nethermind/Nethermind.Merge.Plugin/MergePlugin.cs

@@ -363,7 +363,8 @@ IBlockImprovementContextFactory CreateBlockImprovementContextFactory()
                     _api.SyncPeerPool!,
                     _api.LogManager,
                     _api.Config<IBlocksConfig>().SecondsPerSlot,
-                    _api.Config<IMergeConfig>().SimulateBlockProduction),
+                    _api.Config<IMergeConfig>().SimulateBlockProduction,
+                    _api.Config<IMergeConfig>().ShowExtraData),
                 new GetPayloadBodiesByHashV1Handler(_api.BlockTree, _api.LogManager),
                 new GetPayloadBodiesByRangeV1Handler(_api.BlockTree, _api.LogManager),
                 new GetPayloadBodiesByHashV2Handler(_api.BlockTree, _api.LogManager),

src/Nethermind/Nethermind.Optimism/OptimismPlugin.cs

@@ -257,7 +257,8 @@ public async Task InitRpcModules()
                 _api.SyncPeerPool!,
                 _api.LogManager,
                 _api.Config<IBlocksConfig>().SecondsPerSlot,
-                _api.Config<IMergeConfig>().SimulateBlockProduction),
+                _api.Config<IMergeConfig>().SimulateBlockProduction,
+                _api.Config<IMergeConfig>().ShowExtraData),
             new GetPayloadBodiesByHashV1Handler(_api.BlockTree, _api.LogManager),
             new GetPayloadBodiesByRangeV1Handler(_api.BlockTree, _api.LogManager),
             new GetPayloadBodiesByHashV2Handler(_api.BlockTree, _api.LogManager),