Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Show mev and extra data in block logs #7661

Merged
merged 11 commits into from
Oct 28, 2024
Merged
4 changes: 4 additions & 0 deletions src/Nethermind/Nethermind.Config/BlocksConfig.cs
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";
benaadams marked this conversation as resolved.
Show resolved Hide resolved
}
}
3 changes: 3 additions & 0 deletions src/Nethermind/Nethermind.Config/IBlocksConfig.cs
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();
}
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
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
};
Comment on lines +285 to +290
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we want it hardcoded here? Aren't there more?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These aren't the actual main builders; just ones pretending to be them

95% of mev blocks are picked up by the main pattern where the GasBeneficiary pays the validator in the last tx; these ones pay from a different source.

Really should be in config rather than code, but I have only seen 3 so far

}
}
87 changes: 87 additions & 0 deletions src/Nethermind/Nethermind.Core/Extensions/Bytes.cs
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,91 @@ public static void ChangeEndianness8(Span<byte> bytes)
(BinaryPrimitives.ReverseEndianness(endIth), BinaryPrimitives.ReverseEndianness(ith));
}
}

public static string ToCleanUtf8String(this byte[] bytes)
benaadams marked this conversation as resolved.
Show resolved Hide resolved
{
// 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];
benaadams marked this conversation as resolved.
Show resolved Hide resolved
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;
benaadams marked this conversation as resolved.
Show resolved Hide resolved
}
index += bytesConsumed;
}
else if (status == OperationStatus.InvalidData)
benaadams marked this conversation as resolved.
Show resolved Hide resolved
{
// Invalid data; set flag to add space if needed
if (hasValidContent)
shouldAddSpace = true;
benaadams marked this conversation as resolved.
Show resolved Hide resolved
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;
benaadams marked this conversation as resolved.
Show resolved Hide resolved
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);
}

}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand Down
Loading