Skip to content

Commit

Permalink
Show mev and extra data in block logs (#7661)
Browse files Browse the repository at this point in the history 
Co-authored-by: Lukasz Rozmej <[email protected]>
  • Loading branch information
@benaadams @LukaszRozmej
benaadams and LukaszRozmej authored Oct 28, 2024
1 parent 596b619 commit 3138f0a
Show file tree
Hide file tree
Showing 23 changed files with 214 additions and 48 deletions.
4 changes: 4 additions & 0 deletions src/Nethermind/Nethermind.Config/BlocksConfig.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,5 +53,9 @@ public byte[] GetExtraDataBytes()
{
return _extraDataBytes;
}

public string GasToken { get => GasTokenTicker; set => GasTokenTicker = value; }

public static string GasTokenTicker { get; set; } = "ETH";
}
}
3 changes: 3 additions & 0 deletions src/Nethermind/Nethermind.Config/IBlocksConfig.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -43,5 +43,8 @@ public interface IBlocksConfig : IConfig
[ConfigItem(Description = "The genesis block load timeout, in milliseconds.", DefaultValue = "40000")]
int GenesisTimeoutMs { get; set; }

[ConfigItem(Description = "The ticker that gas rewards are denominated in for processing logs", DefaultValue = "ETH", HiddenFromDocs = true)]
string GasToken { get; set; }

byte[] GetExtraDataBytes();
}
21 changes: 21 additions & 0 deletions src/Nethermind/Nethermind.Consensus/Processing/BlockExtensions.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
using Nethermind.Config;
using Nethermind.Consensus.Producers;
using Nethermind.Core;
using Nethermind.Core.Extensions;
using Nethermind.State.Proofs;

[assembly: InternalsVisibleTo("Nethermind.Consensus.Test")]
Expand Down Expand Up @@ -40,5 +41,25 @@ public static bool IsByNethermindNode(this BlockHeader block) =>
Ascii.IsValid(block.ExtraData)
&& Encoding.ASCII.GetString(block.ExtraData ?? Array.Empty<byte>())
.Contains(BlocksConfig.DefaultExtraData, StringComparison.InvariantCultureIgnoreCase);

public static string ParsedExtraData(this Block block)
{
byte[]? data = block.ExtraData;
if (data is null || data.Length == 0)
{
// If no extra data just show GasBeneficiary address
return $"Address: {(block.Header.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 = new ReadOnlySpan<byte>(data).ToCleanUtf8String();

// 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)}";
}
}
}
5 changes: 3 additions & 2 deletions src/Nethermind/Nethermind.Consensus/Processing/BlockchainProcessor.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -90,7 +90,7 @@ public BlockchainProcessor(
_blockTree.NewBestSuggestedBlock += OnNewBestBlock;
_blockTree.NewHeadBlock += OnNewHeadBlock;

_stats = new ProcessingStats(_logger);
_stats = new ProcessingStats(stateReader, _logger);
}

private void OnNewHeadBlock(object? sender, BlockEventArgs e)
Expand Down Expand Up @@ -419,7 +419,8 @@ private void FireProcessingQueueEmpty()
Metrics.LastBlockProcessingTimeInMs = blockProcessingTimeInMicrosecs / 1000;
Metrics.RecoveryQueueSize = _recoveryQueue.Count;
Metrics.ProcessingQueueSize = _blockQueue.Count;
_stats.UpdateStats(lastProcessed, blockProcessingTimeInMicrosecs);

_stats.UpdateStats(lastProcessed, processingBranch.Root, blockProcessingTimeInMicrosecs);
}

bool updateHead = !options.ContainsFlag(ProcessingOptions.DoNotUpdateHead);
Expand Down
80 changes: 46 additions & 34 deletions src/Nethermind/Nethermind.Consensus/Processing/ProcessingStats.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,21 +2,25 @@
// SPDX-License-Identifier: LGPL-3.0-only

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Threading;
using Nethermind.Blockchain;
using Nethermind.Config;
using Nethermind.Core;
using Nethermind.Core.Crypto;
using Nethermind.Core.Extensions;
using Nethermind.Int256;
using Nethermind.Logging;
using Nethermind.State;

namespace Nethermind.Consensus.Processing
{
//TODO Consult on disabling of such metrics from configuration
internal class ProcessingStats : IThreadPoolWorkItem
{
private readonly IStateReader _stateReader;
private readonly ILogger _logger;
private readonly Stopwatch _processingStopwatch = new();
private readonly Stopwatch _runStopwatch = new();
private long _lastBlockNumber;
private long _lastElapsedRunningMicroseconds;
Expand All @@ -27,17 +31,16 @@ 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;
private Block? _lastBlock;
private Hash256 _lastBranchRoot;
private long _sloadOpcodeProcessing;
private long _sstoreOpcodeProcessing;
private long _callsProcessing;
Expand All @@ -46,8 +49,9 @@ internal class ProcessingStats : IThreadPoolWorkItem
private long _contractAnalysedProcessing;
private long _createsProcessing;

public ProcessingStats(ILogger logger)
public ProcessingStats(IStateReader stateReader, ILogger logger)
{
_stateReader = stateReader;
_logger = logger;

// the line below just to avoid compilation errors
Expand All @@ -57,14 +61,9 @@ public ProcessingStats(ILogger logger)
#endif
}

public void UpdateStats(Block? block, long blockProcessingTimeInMicros)
public void UpdateStats(Block? block, Hash256 branchRoot, long blockProcessingTimeInMicros)
{
if (block is null)
{
return;
}

_processingStopwatch.Stop();
if (block is null) return;

if (_lastBlockNumber == 0)
{
Expand All @@ -83,7 +82,6 @@ public void UpdateStats(Block? block, long blockProcessingTimeInMicros)

Metrics.BlockchainHeight = block.Header.Number;

_blockProcessingMicroseconds = _processingStopwatch.ElapsedMicroseconds();
_runningMicroseconds = _runStopwatch.ElapsedMicroseconds();
_runMicroseconds = (_runningMicroseconds - _lastElapsedRunningMicroseconds);

Expand All @@ -92,6 +90,7 @@ public void UpdateStats(Block? block, long blockProcessingTimeInMicros)
{
_lastReportMs = _reportMs;
_lastBlock = block;
_lastBranchRoot = branchRoot;
_sloadOpcodeProcessing = Evm.Metrics.ThreadLocalSLoadOpcode;
_sstoreOpcodeProcessing = Evm.Metrics.ThreadLocalSStoreOpcode;
_callsProcessing = Evm.Metrics.ThreadLocalCalls;
Expand All @@ -107,6 +106,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";
Expand All @@ -118,10 +118,26 @@ 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;

Transaction[] txs = block.Transactions;
Address beneficiary = block.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(_lastBranchRoot, beneficiary);
UInt256 afterBalance = _stateReader.GetBalance(block.StateRoot, beneficiary);
UInt256 rewards = beforeBalance < afterBalance ? afterBalance - beforeBalance : default;

long currentSelfDestructs = Evm.Metrics.SelfDestructs;

long chunkBlocks = Metrics.Blocks - _lastBlockNumber;
_totalBlocks += chunkBlocks;

double chunkMicroseconds = _chunkProcessingMicroseconds;
double chunkMGas = Metrics.Mgas - _lastTotalMGas;
Expand All @@ -140,21 +156,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);
Expand All @@ -164,7 +175,7 @@ void IThreadPoolWorkItem.Execute()

if (chunkBlocks > 1)
{
_logger.Info($"Processed {block.Number - chunkBlocks + 1,10}...{block.Number,9} | {chunkMs,10:N1} ms | slot {runMs,7:N0} ms |{blockGas}");
_logger.Info($"Processed {block.Number - chunkBlocks + 1,10}...{block.Number,9} | {chunkMs,10:N1} ms | slot {runMs,7:N0} ms |{blockGas}");
}
else
{
Expand All @@ -191,7 +202,7 @@ void IThreadPoolWorkItem.Execute()
< 2000 => orangeText,
_ => redText
};
_logger.Info($"Processed {block.Number,10} | {chunkColor}{chunkMs,10:N1}{resetColor} ms | slot {runMs,7:N0} ms |{blockGas}");
_logger.Info($"Processed {block.Number,10} | {chunkColor}{chunkMs,10:N1}{resetColor} ms | slot {runMs,7:N0} ms |{blockGas}");
}

string mgasPerSecondColor = (mgasPerSecond / (block.GasLimit / 1_000_000.0)) switch
Expand Down Expand Up @@ -235,25 +246,19 @@ 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 x{chunkBlocks,-9:N0} " : $"{(isMev ? " mev" : " ")} {rewards.ToDecimal(null) / weiToEth,5:N4}{BlocksConfig.GasTokenTicker,4}")}{(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}");
_logger.Info($" Block throughput {mgasPerSecondColor}{mgasPerSecond,11:F2}{resetColor} MGas/s{(mgasPerSecond > 1000 ? "🔥" : " ")}| {txps,10:N1} tps | {bps,7:F2} Blk/s | recover {recoveryQueue,5:N0} | process {processingQueue,5:N0}");
}
else
{
_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}");
_logger.Info($" Block throughput {mgasPerSecondColor}{mgasPerSecond,11: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}");
}
}

_lastCachedContractsUsed = _codeDbCacheProcessing;
_lastContractsAnalysed = _contractAnalysedProcessing;
_lastContractsAnalyzed = _contractAnalysedProcessing;
_lastBlockNumber = Metrics.Blocks;
_lastTotalMGas = Metrics.Mgas;
_lastElapsedRunningMicroseconds = _runningMicroseconds;
Expand All @@ -269,12 +274,19 @@ void IThreadPoolWorkItem.Execute()

public void Start()
{
_processingStopwatch.Start();
if (!_runStopwatch.IsRunning)
{
_lastReportMs = Environment.TickCount64;
_runStopwatch.Start();
}
}

// 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)
new Address("0x0b92619DdE55C0cbf828d32993a7fB004E00c84B"), // Extra data as: Builder+ www.btcs.com/builder
};
}
}
90 changes: 90 additions & 0 deletions src/Nethermind/Nethermind.Core/Extensions/Bytes.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@
using Nethermind.Core.Collections;
using Nethermind.Core.Crypto;
using Nethermind.Int256;
using System.Buffers;

namespace Nethermind.Core.Extensions
{
Expand Down Expand Up @@ -1140,5 +1141,94 @@ public static void ChangeEndianness8(Span<byte> bytes)
(BinaryPrimitives.ReverseEndianness(endIth), BinaryPrimitives.ReverseEndianness(ith));
}
}

public static string ToCleanUtf8String(this ReadOnlySpan<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.
char[]? charsArray = null;
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.Slice(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 = ArrayPool<char>.Shared.Rent(newSize);
outputBuffer.Slice(0, outputPos).CopyTo(newBuffer);
outputBuffer = newBuffer;
if (charsArray is not null)
{
ArrayPool<char>.Shared.Return(charsArray);
}
charsArray = newBuffer;
}

rune.EncodeToUtf16(outputBuffer.Slice(outputPos));
outputPos += charsNeeded;
hasValidContent = true;
}
else
{
// Control character encountered; set flag to add space if needed
shouldAddSpace |= hasValidContent;
}
index += bytesConsumed;
}
else if (status == OperationStatus.NeedMoreData)
{
// Incomplete sequence at the end; break out of the loop
break;
}
else
{
// Unexpected status; treat as invalid data
shouldAddSpace |= hasValidContent;
index++;
}
}

// Create the final string from the output buffer.
string outputString = outputPos > 0 ? new string(outputBuffer[..outputPos]) : string.Empty;
if (charsArray is not null)
{
ArrayPool<char>.Shared.Return(charsArray);
}

return outputString;
}

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);
}

}
}
Loading

0 comments on commit 3138f0a

Please sign in to comment.