From 0007a71345d8177413871ee80e13637624b64d18 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Fri, 10 May 2024 23:41:52 +0100 Subject: [PATCH 01/13] Wait for background JumpDestinationAnalysis if in progress --- .../Nethermind.Evm/CodeAnalysis/CodeInfo.cs | 8 +++ .../CodeAnalysis/JumpDestinationAnalyzer.cs | 72 +++++++++++++++++-- .../TransactionProcessor.cs | 2 + .../Nethermind.Evm/VirtualMachine.cs | 4 +- 4 files changed, 78 insertions(+), 8 deletions(-) diff --git a/src/Nethermind/Nethermind.Evm/CodeAnalysis/CodeInfo.cs b/src/Nethermind/Nethermind.Evm/CodeAnalysis/CodeInfo.cs index 6dec8cbd5a4..18c04dc057f 100644 --- a/src/Nethermind/Nethermind.Evm/CodeAnalysis/CodeInfo.cs +++ b/src/Nethermind/Nethermind.Evm/CodeAnalysis/CodeInfo.cs @@ -46,5 +46,13 @@ void IThreadPoolWorkItem.Execute() { _analyzer.Execute(); } + + public void AnalyseInBackgroundIfRequired() + { + if (!ReferenceEquals(_analyzer, _emptyAnalyzer) && _analyzer.RequiresAnalysis) + { + ThreadPool.UnsafeQueueUserWorkItem(this, preferLocal: false); + } + } } } diff --git a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs index 1aa9c500511..136876f9641 100644 --- a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs +++ b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs @@ -6,6 +6,7 @@ using System.Runtime.InteropServices; using System.Runtime.Intrinsics; using System.Runtime.Intrinsics.X86; +using System.Threading; namespace Nethermind.Evm.CodeAnalysis { @@ -19,17 +20,54 @@ public sealed class JumpDestinationAnalyzer(ReadOnlyMemory code) private static readonly long[]? _emptyJumpDestinationBitmap = new long[1]; private long[]? _jumpDestinationBitmap = code.Length == 0 ? _emptyJumpDestinationBitmap : null; + private object? _analysisComplete; private ReadOnlyMemory MachineCode { get; } = code; public bool ValidateJump(int destination) { - ReadOnlySpan machineCode = MachineCode.Span; - _jumpDestinationBitmap ??= CreateJumpDestinationBitmap(machineCode); + _jumpDestinationBitmap ??= CreateOrWaitForJumpDestinationBitmap(); // Cast to uint to change negative numbers to very int high numbers // Then do length check, this both reduces check by 1 and eliminates the bounds // check from accessing the span. - return (uint)destination < (uint)machineCode.Length && IsJumpDestination(_jumpDestinationBitmap, destination); + return (uint)destination < (uint)MachineCode.Length && IsJumpDestination(_jumpDestinationBitmap, destination); + } + + private long[] CreateOrWaitForJumpDestinationBitmap() + { + object? previous = Volatile.Read(ref _analysisComplete); + if (previous is null) + { + ManualResetEventSlim analysisComplete = new(initialState: false); + previous = Interlocked.CompareExchange(ref _analysisComplete, analysisComplete, null); + if (previous is null) + { + // Not already in progress, so start it. + var bitmap = CreateJumpDestinationBitmap(); + _jumpDestinationBitmap = bitmap; + // Release the MRES to be GC'd + _analysisComplete = bitmap; + // Signal complete. + analysisComplete.Set(); + return bitmap; + } + } + else if (previous is ManualResetEventSlim resetEvent) + { + Thread thread = Thread.CurrentThread; + ThreadPriority priority = thread.Priority; + // We are waiting, so drop priority to normal (BlockProcessing runs at higher priority). + thread.Priority = ThreadPriority.Normal; + + // Already in progress, wait for completion. + resetEvent.Wait(); + + // Restore the priority of the thread. + thread.Priority = priority; + } + + // Must be the bitmap, and lost check->create benign data race + return (long[])previous; } /// @@ -55,8 +93,9 @@ private static int GetInt64ArrayLengthFromBitLength(int n) => /// Collects data locations in code. /// An unset bit means the byte is an opcode, a set bit means it's data. /// - private static long[] CreateJumpDestinationBitmap(ReadOnlySpan code) + private long[] CreateJumpDestinationBitmap() { + ReadOnlySpan code = MachineCode.Span; long[] jumpDestinationBitmap = new long[GetInt64ArrayLengthFromBitLength(code.Length)]; int programCounter = 0; // We accumulate each array segment to a register and then flush to memory when we move to next. @@ -146,6 +185,7 @@ private static long[] CreateJumpDestinationBitmap(ReadOnlySpan code) /// /// Checks if the position is in a code segment. /// + [MethodImpl(MethodImplOptions.AggressiveInlining)] private static bool IsJumpDestination(long[] bitvec, int pos) { int vecIndex = pos >> BitShiftPerInt64; @@ -164,8 +204,28 @@ private static void MarkJumpDestinations(long[] jumpDestinationBitmap, int pos, public void Execute() { - // This is to support background thread preparation of the bitmap. - _jumpDestinationBitmap ??= CreateJumpDestinationBitmap(MachineCode.Span); + if (_jumpDestinationBitmap is null && Volatile.Read(ref _analysisComplete) is null) + { + ManualResetEventSlim analysisComplete = new(initialState: false); + if (Interlocked.CompareExchange(ref _analysisComplete, analysisComplete, null) is null) + { + Thread thread = Thread.CurrentThread; + ThreadPriority priority = thread.Priority; + // Boost the priority of the thread as block processing may be waiting on this. + thread.Priority = ThreadPriority.AboveNormal; + + _jumpDestinationBitmap ??= CreateJumpDestinationBitmap(); + + // Release the MRES to be GC'd + _analysisComplete = _jumpDestinationBitmap; + // Signal complete. + analysisComplete.Set(); + // Restore the priority of the thread. + thread.Priority = priority; + } + } } + + public bool RequiresAnalysis => _jumpDestinationBitmap is null; } } diff --git a/src/Nethermind/Nethermind.Evm/TransactionProcessing/TransactionProcessor.cs b/src/Nethermind/Nethermind.Evm/TransactionProcessing/TransactionProcessor.cs index 6d9a4b8f72b..4b97a503590 100644 --- a/src/Nethermind/Nethermind.Evm/TransactionProcessing/TransactionProcessor.cs +++ b/src/Nethermind/Nethermind.Evm/TransactionProcessing/TransactionProcessor.cs @@ -411,6 +411,8 @@ protected ExecutionEnvironment BuildExecutionEnvironment( ? new(tx.Data ?? Memory.Empty) : VirtualMachine.GetCachedCodeInfo(WorldState, recipient, spec); + codeInfo.AnalyseInBackgroundIfRequired(); + byte[] inputData = tx.IsMessageCall ? tx.Data.AsArray() ?? Array.Empty() : Array.Empty(); return new ExecutionEnvironment diff --git a/src/Nethermind/Nethermind.Evm/VirtualMachine.cs b/src/Nethermind/Nethermind.Evm/VirtualMachine.cs index 24cba4cee90..b4ed1b77eba 100644 --- a/src/Nethermind/Nethermind.Evm/VirtualMachine.cs +++ b/src/Nethermind/Nethermind.Evm/VirtualMachine.cs @@ -498,8 +498,7 @@ public TransactionSubstate Run(EvmState state, IWorldState worl public void InsertCode(ReadOnlyMemory code, Address callCodeOwner, IReleaseSpec spec) { var codeInfo = new CodeInfo(code); - // Start generating the JumpDestinationBitmap in background. - ThreadPool.UnsafeQueueUserWorkItem(codeInfo, preferLocal: false); + codeInfo.AnalyseInBackgroundIfRequired(); Hash256 codeHash = code.Length == 0 ? Keccak.OfAnEmptyString : Keccak.Compute(code.Span); _state.InsertCode(callCodeOwner, codeHash, code, spec); @@ -2492,6 +2491,7 @@ private EvmExceptionType InstructionSelfDestruct(EvmState vmState, ref // pointing to data in this tx and will become invalid // for another tx as returned to pool. CodeInfo codeInfo = new(initCode); + codeInfo.AnalyseInBackgroundIfRequired(); ExecutionEnvironment callEnv = new ( From 904bce43de9193b0e01429c3bd8b8aa221d349be Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Fri, 10 May 2024 23:47:55 +0100 Subject: [PATCH 02/13] Tweak --- .../Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs index 136876f9641..4fd6d8cd204 100644 --- a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs +++ b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs @@ -52,7 +52,8 @@ private long[] CreateOrWaitForJumpDestinationBitmap() return bitmap; } } - else if (previous is ManualResetEventSlim resetEvent) + + if (previous is ManualResetEventSlim resetEvent) { Thread thread = Thread.CurrentThread; ThreadPriority priority = thread.Priority; From bdc777151895c18dfd8dea8a62d5d80ecd7f2cb4 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Fri, 10 May 2024 23:59:52 +0100 Subject: [PATCH 03/13] Missed return --- .../Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs index 4fd6d8cd204..609ea4b361f 100644 --- a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs +++ b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs @@ -65,6 +65,7 @@ private long[] CreateOrWaitForJumpDestinationBitmap() // Restore the priority of the thread. thread.Priority = priority; + return _jumpDestinationBitmap; } // Must be the bitmap, and lost check->create benign data race From e1c0a88d9b29307f5717daee44601939472f0ead Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 11 May 2024 16:08:23 +0100 Subject: [PATCH 04/13] Replace logs always 0 with cache vs analysed smartcontracts --- .../Processing/BlockchainProcessor.cs | 4 +++- .../Processing/ProcessingStats.cs | 12 ++++++++---- .../CodeAnalysis/JumpDestinationAnalyzer.cs | 1 + src/Nethermind/Nethermind.Evm/Metrics.cs | 5 +++++ 4 files changed, 17 insertions(+), 5 deletions(-) diff --git a/src/Nethermind/Nethermind.Consensus/Processing/BlockchainProcessor.cs b/src/Nethermind/Nethermind.Consensus/Processing/BlockchainProcessor.cs index 97249d25a39..c3cfb0b7234 100644 --- a/src/Nethermind/Nethermind.Consensus/Processing/BlockchainProcessor.cs +++ b/src/Nethermind/Nethermind.Consensus/Processing/BlockchainProcessor.cs @@ -430,7 +430,9 @@ private void FireProcessingQueueEmpty() if (!readonlyChain) { - _stats.UpdateStats(lastProcessed, _blockTree, _recoveryQueue.Count, _blockQueue.Count, _stopwatch.ElapsedMicroseconds()); + Metrics.RecoveryQueueSize = _recoveryQueue.Count; + Metrics.ProcessingQueueSize = _blockQueue.Count; + _stats.UpdateStats(lastProcessed, _blockTree, _stopwatch.ElapsedMicroseconds()); } return lastProcessed; diff --git a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs index 7ef3faaecb1..b0c18902b4c 100644 --- a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs +++ b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs @@ -39,6 +39,8 @@ internal class ProcessingStats private long _processingMicroseconds; private long _lastTotalCreates; private long _lastReportMs; + private long _lastContractsAnalysed; + private long _lastCachedContractsUsed; public ProcessingStats(ILogger logger) { @@ -51,7 +53,7 @@ public ProcessingStats(ILogger logger) #endif } - public void UpdateStats(Block? block, IBlockTree blockTreeCtx, int recoveryQueueSize, int blockQueueSize, long blockProcessingTimeInMicros) + public void UpdateStats(Block? block, IBlockTree blockTreeCtx, long blockProcessingTimeInMicros) { const string resetColor = "\u001b[37m"; const string whiteText = "\u001b[97m"; @@ -85,8 +87,6 @@ public void UpdateStats(Block? block, IBlockTree blockTreeCtx, int recoveryQueue Metrics.LastDifficulty = block.Difficulty; Metrics.GasUsed = block.GasUsed; Metrics.GasLimit = block.GasLimit; - Metrics.RecoveryQueueSize = recoveryQueueSize; - Metrics.ProcessingQueueSize = blockQueueSize; Metrics.BlockchainHeight = block.Header.Number; Metrics.BestKnownBlockNumber = blockTreeCtx.BestKnownNumber; @@ -117,6 +117,8 @@ public void UpdateStats(Block? block, IBlockTree blockTreeCtx, int recoveryQueue long chunkCreates = Evm.Metrics.Creates - _lastTotalCreates; long chunkSload = Evm.Metrics.SloadOpcode - _lastTotalSLoad; long chunkSstore = Evm.Metrics.SstoreOpcode - _lastTotalSStore; + long contractsAnalysed = Evm.Metrics.ContractsAnalysed - _lastContractsAnalysed; + long cachedContractsUsed = Db.Metrics.CodeDbCache - _lastCachedContractsUsed; double chunkMGas = Metrics.Mgas - _lastTotalMGas; double mgasPerSecond = chunkMicroseconds == 0 ? -1 : chunkMGas / chunkMicroseconds * 1_000_000.0; double totalMgasPerSecond = totalMicroseconds == 0 ? -1 : Metrics.Mgas / totalMicroseconds * 1_000_000.0; @@ -201,7 +203,7 @@ public void UpdateStats(Block? block, IBlockTree blockTreeCtx, int recoveryQueue _ => "" }; _logger.Info($"- Block{(chunkBlocks > 1 ? $"s {chunkBlocks,-9:N0}" : " ")}{(chunkBlocks == 1 ? mgasColor : "")} {chunkMGas,7:F2}{resetColor} MGas | {chunkTx,6: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 throughput {mgasPerSecondColor}{mgasPerSecond,7:F2}{resetColor} MGas/s | {txps,9:F2} t/s | {bps,7:F2} Blk/s | recv {recoveryQueueSize,7:N0} | proc {blockQueueSize,6:N0}"); + _logger.Info($"- Block throughput {mgasPerSecondColor}{mgasPerSecond,7:F2}{resetColor} MGas/s | {txps,9:F2} t/s | {bps,7:F2} Blk/s | scontracts{resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} analysed {contractsAnalysed,5:N0}"); // Only output the total throughput in debug mode if (_logger.IsDebug) { @@ -223,6 +225,8 @@ public void UpdateStats(Block? block, IBlockTree blockTreeCtx, int recoveryQueue } + _lastCachedContractsUsed = Db.Metrics.CodeDbCache; + _lastContractsAnalysed = Evm.Metrics.ContractsAnalysed; _lastReportMs = reportMs; _lastBlockNumber = Metrics.Blocks; _lastTotalMGas = Metrics.Mgas; diff --git a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs index 609ea4b361f..93abcceb3fe 100644 --- a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs +++ b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs @@ -97,6 +97,7 @@ private static int GetInt64ArrayLengthFromBitLength(int n) => /// private long[] CreateJumpDestinationBitmap() { + Metrics.IncrementContractsAnalysed(); ReadOnlySpan code = MachineCode.Span; long[] jumpDestinationBitmap = new long[GetInt64ArrayLengthFromBitLength(code.Length)]; int programCounter = 0; diff --git a/src/Nethermind/Nethermind.Evm/Metrics.cs b/src/Nethermind/Nethermind.Evm/Metrics.cs index 06147b13d47..6dbbfb4329a 100644 --- a/src/Nethermind/Nethermind.Evm/Metrics.cs +++ b/src/Nethermind/Nethermind.Evm/Metrics.cs @@ -3,6 +3,7 @@ using System.ComponentModel; using System.Runtime.CompilerServices; +using System.Threading; using Nethermind.Core.Attributes; @@ -77,6 +78,10 @@ public class Metrics [CounterMetric] [Description("Number of contract create calls.")] public static long Creates { get; set; } + private static long _contractsAnalysed; + public static long ContractsAnalysed => _contractsAnalysed; + public static void IncrementContractsAnalysed() => Interlocked.Increment(ref _contractsAnalysed); + internal static long Transactions { get; set; } internal static float AveGasPrice { get; set; } internal static float MinGasPrice { get; set; } = float.MaxValue; From 88439120c40650b4056e748aa4174e92b5f47281 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 11 May 2024 16:22:05 +0100 Subject: [PATCH 05/13] Add description --- src/Nethermind/Nethermind.Evm/Metrics.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/Nethermind/Nethermind.Evm/Metrics.cs b/src/Nethermind/Nethermind.Evm/Metrics.cs index 6dbbfb4329a..0ede0503c39 100644 --- a/src/Nethermind/Nethermind.Evm/Metrics.cs +++ b/src/Nethermind/Nethermind.Evm/Metrics.cs @@ -79,6 +79,7 @@ public class Metrics [Description("Number of contract create calls.")] public static long Creates { get; set; } private static long _contractsAnalysed; + [Description("Number of contracts' code analysed for jump destinations.")] public static long ContractsAnalysed => _contractsAnalysed; public static void IncrementContractsAnalysed() => Interlocked.Increment(ref _contractsAnalysed); From 0ca4a4e15cde88d37e477d25529ae72ea67d8af4 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sun, 12 May 2024 16:35:56 +0100 Subject: [PATCH 06/13] Move prioirty reset to finally --- .../CodeAnalysis/JumpDestinationAnalyzer.cs | 42 ++++++++++++------- 1 file changed, 27 insertions(+), 15 deletions(-) diff --git a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs index 93abcceb3fe..8ed08d2a21a 100644 --- a/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs +++ b/src/Nethermind/Nethermind.Evm/CodeAnalysis/JumpDestinationAnalyzer.cs @@ -57,14 +57,20 @@ private long[] CreateOrWaitForJumpDestinationBitmap() { Thread thread = Thread.CurrentThread; ThreadPriority priority = thread.Priority; - // We are waiting, so drop priority to normal (BlockProcessing runs at higher priority). - thread.Priority = ThreadPriority.Normal; + try + { + // We are waiting, so drop priority to normal (BlockProcessing runs at higher priority). + thread.Priority = ThreadPriority.Normal; - // Already in progress, wait for completion. - resetEvent.Wait(); + // Already in progress, wait for completion. + resetEvent.Wait(); + } + finally + { + // Restore the priority of the thread. + thread.Priority = priority; + } - // Restore the priority of the thread. - thread.Priority = priority; return _jumpDestinationBitmap; } @@ -214,17 +220,23 @@ public void Execute() { Thread thread = Thread.CurrentThread; ThreadPriority priority = thread.Priority; - // Boost the priority of the thread as block processing may be waiting on this. - thread.Priority = ThreadPriority.AboveNormal; + try + { + // Boost the priority of the thread as block processing may be waiting on this. + thread.Priority = ThreadPriority.AboveNormal; - _jumpDestinationBitmap ??= CreateJumpDestinationBitmap(); + _jumpDestinationBitmap ??= CreateJumpDestinationBitmap(); - // Release the MRES to be GC'd - _analysisComplete = _jumpDestinationBitmap; - // Signal complete. - analysisComplete.Set(); - // Restore the priority of the thread. - thread.Priority = priority; + // Release the MRES to be GC'd + _analysisComplete = _jumpDestinationBitmap; + // Signal complete. + analysisComplete.Set(); + } + finally + { + // Restore the priority of the thread. + thread.Priority = priority; + } } } } From 6e67d5fc40f860167127f70d66a3b528ac6ebd7c Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sun, 12 May 2024 16:51:03 +0100 Subject: [PATCH 07/13] Switch stats modes --- .../Processing/ProcessingStats.cs | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-) diff --git a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs index b0c18902b4c..afabdd0a19c 100644 --- a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs +++ b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs @@ -202,8 +202,22 @@ public void UpdateStats(Block? block, IBlockTree blockTreeCtx, long blockProcess > 75 => whiteText, _ => "" }; + + var recoveryQueue = Metrics.RecoveryQueueSize; + var processingQueue = Metrics.ProcessingQueueSize; + + string extraStats; + if (recoveryQueue > 0 || processingQueue > 0) + { + extraStats = $"recover {recoveryQueue,5:N0} | process {processingQueue,5:N0}"; + } + else + { + extraStats = $"scontracts{resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} analysed {contractsAnalysed,5:N0}"; + } + _logger.Info($"- Block{(chunkBlocks > 1 ? $"s {chunkBlocks,-9:N0}" : " ")}{(chunkBlocks == 1 ? mgasColor : "")} {chunkMGas,7:F2}{resetColor} MGas | {chunkTx,6: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 throughput {mgasPerSecondColor}{mgasPerSecond,7:F2}{resetColor} MGas/s | {txps,9:F2} t/s | {bps,7:F2} Blk/s | scontracts{resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} analysed {contractsAnalysed,5:N0}"); + _logger.Info($"- Block throughput {mgasPerSecondColor}{mgasPerSecond,7:F2}{resetColor} MGas/s | {txps,9:F2} t/s | {bps,7:F2} Blk/s | {extraStats}"); // Only output the total throughput in debug mode if (_logger.IsDebug) { From d2474c82c7c01566dffee084c9fdce8159d8b59e Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sun, 12 May 2024 17:09:55 +0100 Subject: [PATCH 08/13] scontracts -> exec code --- .../Nethermind.Consensus/Processing/ProcessingStats.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs index afabdd0a19c..36d441b92c6 100644 --- a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs +++ b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs @@ -213,7 +213,7 @@ public void UpdateStats(Block? block, IBlockTree blockTreeCtx, long blockProcess } else { - extraStats = $"scontracts{resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} analysed {contractsAnalysed,5:N0}"; + extraStats = $"exec code {resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} new {contractsAnalysed,6:N0}"; } _logger.Info($"- Block{(chunkBlocks > 1 ? $"s {chunkBlocks,-9:N0}" : " ")}{(chunkBlocks == 1 ? mgasColor : "")} {chunkMGas,7:F2}{resetColor} MGas | {chunkTx,6: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}" : "")}"); From 845201a372cd66f9c6ae3dbc9b1c5323bde4f364 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sun, 12 May 2024 17:28:40 +0100 Subject: [PATCH 09/13] Analyse code earlier in CALL --- src/Nethermind/Nethermind.Evm/VirtualMachine.cs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/Nethermind/Nethermind.Evm/VirtualMachine.cs b/src/Nethermind/Nethermind.Evm/VirtualMachine.cs index b4ed1b77eba..aed55846472 100644 --- a/src/Nethermind/Nethermind.Evm/VirtualMachine.cs +++ b/src/Nethermind/Nethermind.Evm/VirtualMachine.cs @@ -2215,6 +2215,9 @@ private EvmExceptionType InstructionCall( !UpdateMemoryCost(vmState, ref gasAvailable, in outputOffset, outputLength) || !UpdateGas(gasExtra, ref gasAvailable)) return EvmExceptionType.OutOfGas; + CodeInfo codeInfo = GetCachedCodeInfo(_worldState, codeSource, spec); + codeInfo.AnalyseInBackgroundIfRequired(); + if (spec.Use63Over64Rule) { gasLimit = UInt256.Min((UInt256)(gasAvailable - gasAvailable / 64), gasLimit); @@ -2268,7 +2271,7 @@ private EvmExceptionType InstructionCall( transferValue: transferValue, value: callValue, inputData: callData, - codeInfo: GetCachedCodeInfo(_worldState, codeSource, spec) + codeInfo: codeInfo ); if (typeof(TLogger) == typeof(IsTracing)) _logger.Trace($"Tx call gas {gasLimitUl}"); if (outputLength == 0) From 7098a0bc2cbf4d19a510879912de7eeae6e22d5c Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sun, 12 May 2024 18:37:07 +0100 Subject: [PATCH 10/13] Analyse on fresh create --- src/Nethermind/Nethermind.Evm/VirtualMachine.cs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/Nethermind/Nethermind.Evm/VirtualMachine.cs b/src/Nethermind/Nethermind.Evm/VirtualMachine.cs index aed55846472..5ee4780c656 100644 --- a/src/Nethermind/Nethermind.Evm/VirtualMachine.cs +++ b/src/Nethermind/Nethermind.Evm/VirtualMachine.cs @@ -543,6 +543,8 @@ public CodeInfo GetCachedCodeInfo(IWorldState worldState, Address codeSource, IR } cachedCodeInfo = new CodeInfo(code); + cachedCodeInfo.AnalyseInBackgroundIfRequired(); + CodeCache.Set(codeHash, cachedCodeInfo); } else From f1a3d4dd4ad75b7182f6face805f64a6c30059c5 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Mon, 13 May 2024 13:20:17 +0100 Subject: [PATCH 11/13] Move Block stats reporting to background thread --- .../Processing/ProcessingStats.cs | 326 +++++++++--------- 1 file changed, 155 insertions(+), 171 deletions(-) diff --git a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs index 36d441b92c6..b80b4fd9d1e 100644 --- a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs +++ b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs @@ -2,8 +2,8 @@ // SPDX-License-Identifier: LGPL-3.0-only using System; -using System.Collections.Generic; using System.Diagnostics; +using System.Threading; using Nethermind.Blockchain; using Nethermind.Core; using Nethermind.Core.Extensions; @@ -13,7 +13,7 @@ namespace Nethermind.Consensus.Processing { //TODO Consult on disabling of such metrics from configuration - internal class ProcessingStats + internal class ProcessingStats : IThreadPoolWorkItem { private readonly ILogger _logger; private readonly Stopwatch _processingStopwatch = new(); @@ -26,21 +26,18 @@ internal class ProcessingStats private long _lastTotalEmptyCalls; private long _lastTotalSLoad; private long _lastTotalSStore; - private long _lastStateDbReads; - private long _lastStateDbWrites; - private long _lastGen0; - private long _lastGen1; - private long _lastGen2; - private long _lastTreeNodeRlp; - private long _lastEvmExceptions; private long _lastSelfDestructs; - private long _maxMemory; private long _totalBlocks; - private long _processingMicroseconds; + private long _chunkProcessingMicroseconds; private long _lastTotalCreates; private long _lastReportMs; private long _lastContractsAnalysed; private long _lastCachedContractsUsed; + private long _blockProcessingMicroseconds; + private long _runningMicroseconds; + private long _runMicroseconds; + private long _reportMs; + private Block? _lastBlock; public ProcessingStats(ILogger logger) { @@ -55,17 +52,6 @@ public ProcessingStats(ILogger logger) public void UpdateStats(Block? block, IBlockTree blockTreeCtx, long blockProcessingTimeInMicros) { - const string resetColor = "\u001b[37m"; - const string whiteText = "\u001b[97m"; - const string yellowText = "\u001b[93m"; - const string orangeText = "\u001b[38;5;208m"; - const string redText = "\u001b[38;5;196m"; - const string greenText = "\u001b[92m"; - const string darkGreenText = "\u001b[32m"; - const string darkCyanText = "\u001b[36m"; - const string blueText = "\u001b[94m"; - const string darkGreyText = resetColor; // "\u001b[90m"; - if (block is null) { return; @@ -78,7 +64,7 @@ public void UpdateStats(Block? block, IBlockTree blockTreeCtx, long blockProcess _lastBlockNumber = block.Number; } - _processingMicroseconds += blockProcessingTimeInMicros; + _chunkProcessingMicroseconds += blockProcessingTimeInMicros; Metrics.Mgas += block.GasUsed / 1_000_000.0; Metrics.Transactions += block.Transactions.Length; @@ -91,173 +77,171 @@ public void UpdateStats(Block? block, IBlockTree blockTreeCtx, long blockProcess Metrics.BlockchainHeight = block.Header.Number; Metrics.BestKnownBlockNumber = blockTreeCtx.BestKnownNumber; - long processingMicroseconds = _processingStopwatch.ElapsedMicroseconds(); - long runningMicroseconds = _runStopwatch.ElapsedMicroseconds(); - long runMicroseconds = (runningMicroseconds - _lastElapsedRunningMicroseconds); + _blockProcessingMicroseconds = _processingStopwatch.ElapsedMicroseconds(); + _runningMicroseconds = _runStopwatch.ElapsedMicroseconds(); + _runMicroseconds = (_runningMicroseconds - _lastElapsedRunningMicroseconds); - long reportMs = Environment.TickCount64; + long reportMs = _reportMs = Environment.TickCount64; if (reportMs - _lastReportMs > 1000) { - long currentStateDbReads = Db.Metrics.DbReads.GetValueOrDefault("StateDb"); - long currentStateDbWrites = Db.Metrics.DbWrites.GetValueOrDefault("StateDb"); - long currentTreeNodeRlp = Trie.Metrics.TreeNodeRlpEncodings + Trie.Metrics.TreeNodeRlpDecodings; - long evmExceptions = Evm.Metrics.EvmExceptions; - long currentSelfDestructs = Evm.Metrics.SelfDestructs; + _lastReportMs = _reportMs; + _lastBlock = block; + GenerateReport(); + } + } - long chunkBlocks = Metrics.Blocks - _lastBlockNumber; - _totalBlocks += chunkBlocks; + private void GenerateReport() => ThreadPool.UnsafeQueueUserWorkItem(this, preferLocal: false); - if (_logger.IsInfo) - { - double chunkMicroseconds = _processingMicroseconds; - double totalMicroseconds = processingMicroseconds; - long chunkTx = Metrics.Transactions - _lastTotalTx; - long chunkCalls = Evm.Metrics.Calls - _lastTotalCalls; - long chunkEmptyCalls = Evm.Metrics.EmptyCalls - _lastTotalEmptyCalls; - long chunkCreates = Evm.Metrics.Creates - _lastTotalCreates; - long chunkSload = Evm.Metrics.SloadOpcode - _lastTotalSLoad; - long chunkSstore = Evm.Metrics.SstoreOpcode - _lastTotalSStore; - long contractsAnalysed = Evm.Metrics.ContractsAnalysed - _lastContractsAnalysed; - long cachedContractsUsed = Db.Metrics.CodeDbCache - _lastCachedContractsUsed; - double chunkMGas = Metrics.Mgas - _lastTotalMGas; - double mgasPerSecond = chunkMicroseconds == 0 ? -1 : chunkMGas / chunkMicroseconds * 1_000_000.0; - 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); - double runMs = (runMicroseconds == 0 ? -1 : runMicroseconds / 1000.0); - string blockGas = Evm.Metrics.BlockMinGasPrice != float.MaxValue ? $"⛽ Gas gwei: {Evm.Metrics.BlockMinGasPrice:N2} .. {whiteText}{Math.Max(Evm.Metrics.BlockMinGasPrice, Evm.Metrics.BlockEstMedianGasPrice):N2}{resetColor} ({Evm.Metrics.BlockAveGasPrice:N2}) .. {Evm.Metrics.BlockMaxGasPrice:N2}" : ""; - string mgasColor = whiteText; + void IThreadPoolWorkItem.Execute() + { + const string resetColor = "\u001b[37m"; + const string whiteText = "\u001b[97m"; + const string yellowText = "\u001b[93m"; + const string orangeText = "\u001b[38;5;208m"; + const string redText = "\u001b[38;5;196m"; + const string greenText = "\u001b[92m"; + const string darkGreenText = "\u001b[32m"; + const string darkCyanText = "\u001b[36m"; + const string blueText = "\u001b[94m"; + const string darkGreyText = resetColor; // "\u001b[90m"; - Metrics.MgasPerSec = mgasPerSecond; + long currentSelfDestructs = Evm.Metrics.SelfDestructs; - if (chunkBlocks > 1) - { - _logger.Info($"Processed {block.Number - chunkBlocks + 1,9}...{block.Number,9} | {chunkMs,9:N2} ms | slot {runMs,7:N0} ms |{blockGas}"); - } - else - { - mgasColor = (chunkMGas / (block.GasLimit / 16_000_000.0)) switch - { - // At 30M gas limit the values are in comments - > 15 => redText, // 28.125 MGas - > 14 => orangeText, // 26.25 MGas - > 13 => yellowText, // 24.375 MGas - > 10 => darkGreenText, // 18.75 MGas - > 7 => greenText, // 13.125 MGas - > 6 => darkGreenText, // 11.25 MGas - > 5 => whiteText, // 9.375 MGas - > 4 => resetColor, // 7.5 MGas - > 3 => darkCyanText, // 5.625 MGas - _ => blueText - }; - var chunkColor = chunkMs switch - { - < 200 => greenText, - < 300 => darkGreenText, - < 500 => whiteText, - < 1000 => yellowText, - < 2000 => orangeText, - _ => redText - }; - _logger.Info($"Processed {block.Number,9} | {chunkColor}{chunkMs,9:N2}{resetColor} ms | slot {runMs,7:N0} ms |{blockGas}"); - } + long chunkBlocks = Metrics.Blocks - _lastBlockNumber; + _totalBlocks += chunkBlocks; + + double chunkMGas = Metrics.Mgas - _lastTotalMGas; + double chunkMicroseconds = _chunkProcessingMicroseconds; + double mgasPerSecond = chunkMicroseconds == 0 ? -1 : chunkMGas / chunkMicroseconds * 1_000_000.0; + Metrics.MgasPerSec = mgasPerSecond; - string mgasPerSecondColor = (mgasPerSecond / (block.GasLimit / 1_000_000.0)) switch + Block? block = Interlocked.Exchange(ref _lastBlock, null); + if (block is not null && _logger.IsInfo) + { + double totalMicroseconds = _blockProcessingMicroseconds; + long chunkTx = Metrics.Transactions - _lastTotalTx; + long chunkCalls = Evm.Metrics.Calls - _lastTotalCalls; + long chunkEmptyCalls = Evm.Metrics.EmptyCalls - _lastTotalEmptyCalls; + long chunkCreates = Evm.Metrics.Creates - _lastTotalCreates; + long chunkSload = Evm.Metrics.SloadOpcode - _lastTotalSLoad; + long chunkSstore = Evm.Metrics.SstoreOpcode - _lastTotalSStore; + long contractsAnalysed = Evm.Metrics.ContractsAnalysed - _lastContractsAnalysed; + long cachedContractsUsed = Db.Metrics.CodeDbCache - _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); + double runMs = (_runMicroseconds == 0 ? -1 : _runMicroseconds / 1000.0); + string blockGas = Evm.Metrics.BlockMinGasPrice != float.MaxValue ? $"⛽ Gas gwei: {Evm.Metrics.BlockMinGasPrice:N2} .. {whiteText}{Math.Max(Evm.Metrics.BlockMinGasPrice, Evm.Metrics.BlockEstMedianGasPrice):N2}{resetColor} ({Evm.Metrics.BlockAveGasPrice:N2}) .. {Evm.Metrics.BlockMaxGasPrice:N2}" : ""; + string mgasColor = whiteText; + + if (chunkBlocks > 1) + { + _logger.Info($"Processed {block.Number - chunkBlocks + 1,9}...{block.Number,9} | {chunkMs,9:N2} ms | slot {runMs,7:N0} ms |{blockGas}"); + } + else + { + mgasColor = (chunkMGas / (block.GasLimit / 16_000_000.0)) switch { // At 30M gas limit the values are in comments - > 3 => greenText, // 90 MGas/s - > 2.5f => darkGreenText, // 75 MGas/s - > 2 => whiteText, // 60 MGas/s - > 1.5f => resetColor, // 45 MGas/s - > 1 => yellowText, // 30 MGas/s - > 0.5f => orangeText, // 15 MGas/s - _ => redText - }; - var sstoreColor = chunkBlocks > 1 ? "" : chunkSstore switch - { - > 3500 => redText, - > 2500 => orangeText, - > 2000 => yellowText, - > 1500 => whiteText, - > 900 when chunkCalls > 900 => whiteText, - _ => "" - }; - var callsColor = chunkBlocks > 1 ? "" : chunkCalls switch - { - > 3500 => redText, - > 2500 => orangeText, - > 2000 => yellowText, - > 1500 => whiteText, - > 900 when chunkSstore > 900 => whiteText, - _ => "" + > 15 => redText, // 28.125 MGas + > 14 => orangeText, // 26.25 MGas + > 13 => yellowText, // 24.375 MGas + > 10 => darkGreenText, // 18.75 MGas + > 7 => greenText, // 13.125 MGas + > 6 => darkGreenText, // 11.25 MGas + > 5 => whiteText, // 9.375 MGas + > 4 => resetColor, // 7.5 MGas + > 3 => darkCyanText, // 5.625 MGas + _ => blueText }; - var createsColor = chunkBlocks > 1 ? "" : chunkCreates switch + var chunkColor = chunkMs switch { - > 300 => redText, - > 200 => orangeText, - > 150 => yellowText, - > 75 => whiteText, - _ => "" + < 200 => greenText, + < 300 => darkGreenText, + < 500 => whiteText, + < 1000 => yellowText, + < 2000 => orangeText, + _ => redText }; + _logger.Info($"Processed {block.Number,9} | {chunkColor}{chunkMs,9:N2}{resetColor} ms | slot {runMs,7:N0} ms |{blockGas}"); + } - var recoveryQueue = Metrics.RecoveryQueueSize; - var processingQueue = Metrics.ProcessingQueueSize; - - string extraStats; - if (recoveryQueue > 0 || processingQueue > 0) - { - extraStats = $"recover {recoveryQueue,5:N0} | process {processingQueue,5:N0}"; - } - else - { - extraStats = $"exec code {resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} new {contractsAnalysed,6:N0}"; - } - - _logger.Info($"- Block{(chunkBlocks > 1 ? $"s {chunkBlocks,-9:N0}" : " ")}{(chunkBlocks == 1 ? mgasColor : "")} {chunkMGas,7:F2}{resetColor} MGas | {chunkTx,6: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 throughput {mgasPerSecondColor}{mgasPerSecond,7:F2}{resetColor} MGas/s | {txps,9:F2} t/s | {bps,7:F2} Blk/s | {extraStats}"); - // Only output the total throughput in debug mode - if (_logger.IsDebug) - { - _logger.Debug($"- Total throughput {totalMgasPerSecond,7:F2} MGas/s | {totalTxPerSecond,9:F2} t/s | {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}"); - } + string mgasPerSecondColor = (mgasPerSecond / (block.GasLimit / 1_000_000.0)) switch + { + // At 30M gas limit the values are in comments + > 3 => greenText, // 90 MGas/s + > 2.5f => darkGreenText, // 75 MGas/s + > 2 => whiteText, // 60 MGas/s + > 1.5f => resetColor, // 45 MGas/s + > 1 => yellowText, // 30 MGas/s + > 0.5f => orangeText, // 15 MGas/s + _ => redText + }; + var sstoreColor = chunkBlocks > 1 ? "" : chunkSstore switch + { + > 3500 => redText, + > 2500 => orangeText, + > 2000 => yellowText, + > 1500 => whiteText, + > 900 when chunkCalls > 900 => whiteText, + _ => "" + }; + var callsColor = chunkBlocks > 1 ? "" : chunkCalls switch + { + > 3500 => redText, + > 2500 => orangeText, + > 2000 => yellowText, + > 1500 => whiteText, + > 900 when chunkSstore > 900 => whiteText, + _ => "" + }; + var createsColor = chunkBlocks > 1 ? "" : chunkCreates switch + { + > 300 => redText, + > 200 => orangeText, + > 150 => yellowText, + > 75 => whiteText, + _ => "" + }; - if (_logger.IsTrace) - { - long currentGen0 = GC.CollectionCount(0); - long currentGen1 = GC.CollectionCount(1); - long currentGen2 = GC.CollectionCount(2); - long currentMemory = GC.GetTotalMemory(false); - _maxMemory = Math.Max(_maxMemory, currentMemory); - _logger.Trace($"Gen0 {currentGen0 - _lastGen0,6}, Gen1 {currentGen1 - _lastGen1,6}, Gen2 {currentGen2 - _lastGen2,6}, maxmem {_maxMemory / 1000000,5}, mem {currentMemory / 1000000,5}, reads {currentStateDbReads - _lastStateDbReads,9}, writes {currentStateDbWrites - _lastStateDbWrites,9}, rlp {currentTreeNodeRlp - _lastTreeNodeRlp,9}, exceptions {evmExceptions - _lastEvmExceptions}, selfdstrcs {currentSelfDestructs - _lastSelfDestructs}"); - _lastGen0 = currentGen0; - _lastGen1 = currentGen1; - _lastGen2 = currentGen2; - } + var recoveryQueue = Metrics.RecoveryQueueSize; + var processingQueue = Metrics.ProcessingQueueSize; + string extraStats; + if (recoveryQueue > 0 || processingQueue > 0) + { + extraStats = $"recover {recoveryQueue,5:N0} | process {processingQueue,5:N0}"; + } + else + { + extraStats = $"exec code {resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} new {contractsAnalysed,6:N0}"; } - _lastCachedContractsUsed = Db.Metrics.CodeDbCache; - _lastContractsAnalysed = Evm.Metrics.ContractsAnalysed; - _lastReportMs = reportMs; - _lastBlockNumber = Metrics.Blocks; - _lastTotalMGas = Metrics.Mgas; - _lastElapsedRunningMicroseconds = runningMicroseconds; - _lastTotalTx = Metrics.Transactions; - _lastTotalCalls = Evm.Metrics.Calls; - _lastTotalEmptyCalls = Evm.Metrics.EmptyCalls; - _lastTotalCreates = Evm.Metrics.Creates; - _lastTotalSLoad = Evm.Metrics.SloadOpcode; - _lastTotalSStore = Evm.Metrics.SstoreOpcode; - _lastStateDbReads = currentStateDbReads; - _lastStateDbWrites = currentStateDbWrites; - _lastTreeNodeRlp = currentTreeNodeRlp; - _lastEvmExceptions = evmExceptions; - _lastSelfDestructs = currentSelfDestructs; - _processingMicroseconds = 0; + _logger.Info($"- Block{(chunkBlocks > 1 ? $"s {chunkBlocks,-9:N0}" : " ")}{(chunkBlocks == 1 ? mgasColor : "")} {chunkMGas,7:F2}{resetColor} MGas | {chunkTx,6: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 throughput {mgasPerSecondColor}{mgasPerSecond,7:F2}{resetColor} MGas/s | {txps,9:F2} t/s | {bps,7:F2} Blk/s | {extraStats}"); + // Only output the total throughput in debug mode + if (_logger.IsDebug) + { + _logger.Debug($"- Total throughput {totalMgasPerSecond,7:F2} MGas/s | {totalTxPerSecond,9:F2} t/s | {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 = Db.Metrics.CodeDbCache; + _lastContractsAnalysed = Evm.Metrics.ContractsAnalysed; + _lastBlockNumber = Metrics.Blocks; + _lastTotalMGas = Metrics.Mgas; + _lastElapsedRunningMicroseconds = _runningMicroseconds; + _lastTotalTx = Metrics.Transactions; + _lastTotalCalls = Evm.Metrics.Calls; + _lastTotalEmptyCalls = Evm.Metrics.EmptyCalls; + _lastTotalCreates = Evm.Metrics.Creates; + _lastTotalSLoad = Evm.Metrics.SloadOpcode; + _lastTotalSStore = Evm.Metrics.SstoreOpcode; + _lastSelfDestructs = currentSelfDestructs; + _chunkProcessingMicroseconds = 0; } public void Start() From 59c900c7952fc69f2fa7edccddd088460d8189ed Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Mon, 13 May 2024 15:09:32 +0100 Subject: [PATCH 12/13] Use two string interpolations --- .../Nethermind.Consensus/Processing/ProcessingStats.cs | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs index b80b4fd9d1e..b41547933fb 100644 --- a/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs +++ b/src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs @@ -210,18 +210,16 @@ void IThreadPoolWorkItem.Execute() var recoveryQueue = Metrics.RecoveryQueueSize; var processingQueue = Metrics.ProcessingQueueSize; - string extraStats; + _logger.Info($"- Block{(chunkBlocks > 1 ? $"s {chunkBlocks,-9:N0}" : " ")}{(chunkBlocks == 1 ? mgasColor : "")} {chunkMGas,7:F2}{resetColor} MGas | {chunkTx,6: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) { - extraStats = $"recover {recoveryQueue,5:N0} | process {processingQueue,5:N0}"; + _logger.Info($"- Block throughput {mgasPerSecondColor}{mgasPerSecond,7:F2}{resetColor} MGas/s | {txps,9:F2} t/s | {bps,7:F2} Blk/s | recover {recoveryQueue,5:N0} | process {processingQueue,5:N0}"); } else { - extraStats = $"exec code {resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} new {contractsAnalysed,6:N0}"; + _logger.Info($"- Block throughput {mgasPerSecondColor}{mgasPerSecond,7:F2}{resetColor} MGas/s | {txps,9:F2} t/s | {bps,7:F2} Blk/s | exec code {resetColor} from cache {cachedContractsUsed,7:N0} |{resetColor} new {contractsAnalysed,6:N0}"); } - _logger.Info($"- Block{(chunkBlocks > 1 ? $"s {chunkBlocks,-9:N0}" : " ")}{(chunkBlocks == 1 ? mgasColor : "")} {chunkMGas,7:F2}{resetColor} MGas | {chunkTx,6: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 throughput {mgasPerSecondColor}{mgasPerSecond,7:F2}{resetColor} MGas/s | {txps,9:F2} t/s | {bps,7:F2} Blk/s | {extraStats}"); // Only output the total throughput in debug mode if (_logger.IsDebug) { From 4eee7f642efc4f67a37d165e339f7e6b90942938 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Mon, 13 May 2024 18:38:26 +0100 Subject: [PATCH 13/13] Alternate Peers report --- .../Reporting/SyncReport.cs | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index f51748f0b49..f088c7b1430 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -134,6 +134,7 @@ private static string Pad(long value, int length) private string _paddedAmountOfOldReceiptsToDownload; private long _amountOfBodiesToDownload; private long _amountOfReceiptsToDownload; + private uint _nodeInfoType; private void SetPaddedPivots() { @@ -175,8 +176,14 @@ private void WriteSyncReport() { if (_reportId % PeerCountFrequency == 0) { - _logger.Info(_syncPeersReport.MakeSummaryReportForPeers(_syncPeerPool.InitializedPeers, $"Peers | with best block: {_syncPeerPool.InitializedPeersCount} | all: {_syncPeerPool.PeerCount}")); - _logger.Info(_syncPeersReport.MakeDiversityReportForPeers(_syncPeerPool.InitializedPeers, $"Peers | node diversity : ")); + if (_nodeInfoType++ % 2 == 0) + { + _logger.Info(_syncPeersReport.MakeSummaryReportForPeers(_syncPeerPool.InitializedPeers, $"Peers | with best block: {_syncPeerPool.InitializedPeersCount} | all: {_syncPeerPool.PeerCount}")); + } + else + { + _logger.Info(_syncPeersReport.MakeDiversityReportForPeers(_syncPeerPool.InitializedPeers, $"Peers | node diversity : ")); + } } }