diff --git a/src/Nethermind/Nethermind.Analytics/AnalyticsRpcModule.cs b/src/Nethermind/Nethermind.Analytics/AnalyticsRpcModule.cs index 7a4755d3124..da7d5042fa0 100644 --- a/src/Nethermind/Nethermind.Analytics/AnalyticsRpcModule.cs +++ b/src/Nethermind/Nethermind.Analytics/AnalyticsRpcModule.cs @@ -4,6 +4,7 @@ using System; using System.Threading; using Nethermind.Blockchain; +using Nethermind.Core; using Nethermind.Int256; using Nethermind.JsonRpc; using Nethermind.Logging; @@ -26,7 +27,8 @@ public AnalyticsRpcModule(IBlockTree blockTree, IStateReader stateReader, ILogMa public ResultWrapper analytics_verifySupply() { - SupplyVerifier supplyVerifier = new SupplyVerifier(_logManager.GetClassLogger()); + ProgressLogger progressLogger = new ProgressLogger("Supply Verification", _logManager); + SupplyVerifier supplyVerifier = new SupplyVerifier(_logManager.GetClassLogger(), progressLogger); _stateReader.RunTreeVisitor(supplyVerifier, _blockTree.Head.StateRoot); return ResultWrapper.Success(supplyVerifier.Balance); } diff --git a/src/Nethermind/Nethermind.Analytics/SupplyVerifier.cs b/src/Nethermind/Nethermind.Analytics/SupplyVerifier.cs index 5e53bd49230..739a65e7ab5 100644 --- a/src/Nethermind/Nethermind.Analytics/SupplyVerifier.cs +++ b/src/Nethermind/Nethermind.Analytics/SupplyVerifier.cs @@ -18,10 +18,12 @@ public class SupplyVerifier : ITreeVisitor private readonly HashSet.AlternateLookup _ignoreThisOneLookup; private int _accountsVisited; private int _nodesVisited; + private readonly ProgressLogger _progressLogger; - public SupplyVerifier(ILogger logger) + public SupplyVerifier(ILogger logger, ProgressLogger progressLogger) { _logger = logger; + _progressLogger = progressLogger ?? throw new ArgumentNullException(nameof(progressLogger)); _ignoreThisOneLookup = _ignoreThisOne.GetAlternateLookup(); } @@ -46,6 +48,7 @@ public bool ShouldVisit(in OldStyleTrieVisitContext _, in ValueHash256 nextNode) public void VisitTree(in OldStyleTrieVisitContext _, in ValueHash256 rootHash) { + _progressLogger.Reset(0, 0); // We'll update as we go since we don't know total nodes upfront } public void VisitMissingNode(in OldStyleTrieVisitContext _, in ValueHash256 nodeHash) @@ -55,9 +58,16 @@ public void VisitMissingNode(in OldStyleTrieVisitContext _, in ValueHash256 node public void VisitBranch(in OldStyleTrieVisitContext trieVisitContext, TrieNode node) { - _logger.Info($"Balance after visiting {_accountsVisited} accounts and {_nodesVisited} nodes: {Balance}"); _nodesVisited++; + _progressLogger.Update(_nodesVisited); + + // Log progress every 1000 nodes + if (_nodesVisited % 1000 == 0) + { + _progressLogger.LogProgress(); + } + if (trieVisitContext.IsStorage) { for (int i = 0; i < 16; i++) @@ -74,6 +84,9 @@ public void VisitBranch(in OldStyleTrieVisitContext trieVisitContext, TrieNode n public void VisitExtension(in OldStyleTrieVisitContext trieVisitContext, TrieNode node) { _nodesVisited++; + + _progressLogger.Update(_nodesVisited); + if (trieVisitContext.IsStorage) { _ignoreThisOne.Add(node.GetChildHash(0)); @@ -90,7 +103,13 @@ public void VisitAccount(in OldStyleTrieVisitContext _, TrieNode node, in Accoun Balance += account.Balance; _accountsVisited++; - _logger.Info($"Balance after visiting {_accountsVisited} accounts and {_nodesVisited} nodes: {Balance}"); + _progressLogger.Update(_nodesVisited); + + // Log progress every 1000 accounts + if (_accountsVisited % 1000 == 0) + { + _progressLogger.LogProgress(); + } } } } diff --git a/src/Nethermind/Nethermind.Blockchain.Test/FullPruning/CopyTreeVisitorTests.cs b/src/Nethermind/Nethermind.Blockchain.Test/FullPruning/CopyTreeVisitorTests.cs index a2038bb3ae3..c311bdfdffe 100644 --- a/src/Nethermind/Nethermind.Blockchain.Test/FullPruning/CopyTreeVisitorTests.cs +++ b/src/Nethermind/Nethermind.Blockchain.Test/FullPruning/CopyTreeVisitorTests.cs @@ -96,14 +96,16 @@ private IPruningContext CopyDb(IPruningContext pruningContext, CancellationToken if (_keyScheme == INodeStorage.KeyScheme.Hash) { NodeStorage nodeStorage = new NodeStorage(pruningContext, _keyScheme); - using CopyTreeVisitor copyTreeVisitor = new(nodeStorage, writeFlags, logManager, cancellationToken); + ProgressLogger progressLogger = new ProgressLogger("Copy Tree", logManager); + using CopyTreeVisitor copyTreeVisitor = new(nodeStorage, writeFlags, logManager, cancellationToken, progressLogger); stateReader.RunTreeVisitor(copyTreeVisitor, trie.RootHash, visitingOptions); copyTreeVisitor.Finish(); } else { NodeStorage nodeStorage = new NodeStorage(pruningContext, _keyScheme); - using CopyTreeVisitor copyTreeVisitor = new(nodeStorage, writeFlags, logManager, cancellationToken); + ProgressLogger progressLogger = new ProgressLogger("Copy Tree", logManager); + using CopyTreeVisitor copyTreeVisitor = new(nodeStorage, writeFlags, logManager, cancellationToken, progressLogger); stateReader.RunTreeVisitor(copyTreeVisitor, trie.RootHash, visitingOptions); copyTreeVisitor.Finish(); } diff --git a/src/Nethermind/Nethermind.Blockchain/FullPruning/CopyTreeVisitor.cs b/src/Nethermind/Nethermind.Blockchain/FullPruning/CopyTreeVisitor.cs index 94a9d7454db..0e2e8d04418 100644 --- a/src/Nethermind/Nethermind.Blockchain/FullPruning/CopyTreeVisitor.cs +++ b/src/Nethermind/Nethermind.Blockchain/FullPruning/CopyTreeVisitor.cs @@ -25,23 +25,29 @@ public class CopyTreeVisitor : ICopyTreeVisitor, ITreeVisitor true; @@ -54,6 +60,13 @@ public void VisitTree(in TContext nodeContext, in ValueHash256 rootHash) { _stopwatch.Start(); if (_logger.IsInfo) _logger.Info($"Full Pruning Started on root hash {rootHash}: do not close the node until finished or progress will be lost."); + + // Initialize total nodes to process - we don't estimate since full pruning + // may not copy all nodes and the actual count depends on pruning strategy + _totalNodesToProcess = 0; // We'll track progress without a target + + // Initialize progress logger + _progressLogger.Reset(0, _totalNodesToProcess); } [DoesNotReturn, StackTraceHidden] @@ -82,12 +95,14 @@ private void PersistNode(Hash256 storage, in TreePath path, TrieNode node) { // simple copy of nodes RLP _concurrentWriteBatcher.Set(storage, path, node.Keccak, node.FullRlp.ToArray(), _writeFlags); - Interlocked.Increment(ref _persistedNodes); + long currentNodes = Interlocked.Increment(ref _persistedNodes); + + _progressLogger.Update(currentNodes); - // log message every 1 mln nodes - if (_persistedNodes % Million == 0) + // Log progress every 1 million nodes or when progress logger suggests + if (currentNodes % Million == 0) { - LogProgress("In Progress"); + _progressLogger.LogProgress(); } } } @@ -95,7 +110,28 @@ private void PersistNode(Hash256 storage, in TreePath path, TrieNode node) private void LogProgress(string state) { if (_logger.IsInfo) - _logger.Info($"Full Pruning {state}: {_stopwatch.Elapsed} {_persistedNodes / (double)Million:N} mln nodes mirrored."); + { + var elapsed = _stopwatch.Elapsed; + var nodesPerSecond = elapsed.TotalSeconds > 0 ? _persistedNodes / elapsed.TotalSeconds : 0; + + _logger.Info($"Full Pruning {state}: {elapsed} | " + + $"Nodes: {_persistedNodes:N0} | " + + $"Speed: {nodesPerSecond:N0} nodes/sec | " + + $"Mirrored: {_persistedNodes / (double)Million:N} mln nodes"); + } + } + + /// + /// Estimates the number of nodes in the state trie for progress tracking. + /// This is a rough estimate since full pruning may not copy all nodes. + /// + private long EstimateNodesInState(ValueHash256 rootHash) + { + // Since we cannot accurately estimate the number of nodes that will be copied + // during full pruning (as it depends on the pruning strategy and state structure), + // we return 0 to indicate that we don't have a target value. + // ProgressLogger will handle this by showing only current progress without percentage. + return 0; } public void Dispose() @@ -109,7 +145,10 @@ public void Dispose() public void Finish() { _finished = true; - LogProgress("Finished"); + + _progressLogger.MarkEnd(); + _progressLogger.LogProgress(); + _concurrentWriteBatcher.Dispose(); } } diff --git a/src/Nethermind/Nethermind.Blockchain/FullPruning/FullPruner.cs b/src/Nethermind/Nethermind.Blockchain/FullPruning/FullPruner.cs index 01ee4f9cde9..cda84421e0f 100644 --- a/src/Nethermind/Nethermind.Blockchain/FullPruning/FullPruner.cs +++ b/src/Nethermind/Nethermind.Blockchain/FullPruning/FullPruner.cs @@ -39,6 +39,7 @@ public class FullPruner : IDisposable private readonly ILogger _logger; private readonly TimeSpan _minimumPruningDelay; private DateTime _lastPruning = DateTime.MinValue; + private readonly ProgressLogger _progressLogger; public FullPruner( IFullPruningDb fullPruningDb, @@ -69,6 +70,7 @@ public FullPruner( _pruningTrigger.Prune += OnPrune; _logger = _logManager.GetClassLogger(); _minimumPruningDelay = TimeSpan.FromHours(_pruningConfig.FullPruningMinimumDelayHours); + _progressLogger = new ProgressLogger("Full Pruning", logManager); if (_pruningConfig.FullPruningCompletionBehavior != FullPruningCompletionBehavior.None) { @@ -264,6 +266,9 @@ private Task CopyTrie(IPruningContext pruning, Hash256 stateRoot, CancellationTo }; if (_logger.IsInfo) _logger.Info($"Full pruning started with MaxDegreeOfParallelism: {visitingOptions.MaxDegreeOfParallelism} and FullScanMemoryBudget: {visitingOptions.FullScanMemoryBudget}"); + // Initialize progress logger for trie copying + _progressLogger.Reset(0, 0); // We'll update the target value when we know the total nodes + visitor = targetNodeStorage.Scheme == INodeStorage.KeyScheme.Hash ? CopyTree(stateRoot, targetNodeStorage, writeFlags, visitingOptions, cancellationToken) : CopyTree(stateRoot, targetNodeStorage, writeFlags, visitingOptions, cancellationToken); @@ -303,7 +308,7 @@ private ICopyTreeVisitor CopyTree( CancellationToken cancellationToken ) where TContext : struct, ITreePathContextWithStorage, INodeContext { - CopyTreeVisitor copyTreeVisitor = new(targetNodeStorage, writeFlags, _logManager, cancellationToken); + CopyTreeVisitor copyTreeVisitor = new(targetNodeStorage, writeFlags, _logManager, cancellationToken, _progressLogger); _stateReader.RunTreeVisitor(copyTreeVisitor, stateRoot, visitingOptions); return copyTreeVisitor; } diff --git a/src/Nethermind/Nethermind.Init/Steps/Migrations/TotalDifficultyFixMigration.cs b/src/Nethermind/Nethermind.Init/Steps/Migrations/TotalDifficultyFixMigration.cs index 99271552330..f8e731d77d3 100644 --- a/src/Nethermind/Nethermind.Init/Steps/Migrations/TotalDifficultyFixMigration.cs +++ b/src/Nethermind/Nethermind.Init/Steps/Migrations/TotalDifficultyFixMigration.cs @@ -20,6 +20,7 @@ public class TotalDifficultyFixMigration : IDatabaseMigration private readonly ISyncConfig _syncConfig; private readonly IChainLevelInfoRepository _chainLevelInfoRepository; private readonly IBlockTree _blockTree; + private readonly ProgressLogger _progressLogger; public TotalDifficultyFixMigration(IChainLevelInfoRepository? chainLevelInfoRepository, IBlockTree? blockTree, ISyncConfig syncConfig, ILogManager logManager) { @@ -27,6 +28,7 @@ public TotalDifficultyFixMigration(IChainLevelInfoRepository? chainLevelInfoRepo _blockTree = blockTree ?? throw new ArgumentNullException(nameof(blockTree)); _logger = logManager.GetClassLogger(); _syncConfig = syncConfig; + _progressLogger = new ProgressLogger("TotalDifficulty Fix", logManager); } public Task Run(CancellationToken cancellationToken) @@ -52,6 +54,12 @@ private void RunMigration(long startingBlock, long? lastBlock, CancellationToken if (_logger.IsInfo) _logger.Info($"Starting TotalDifficultyFixMigration. From block {startingBlock} to block {lastBlock}"); + long totalBlocks = lastBlock.Value - startingBlock + 1; + long processedBlocks = 0; + long fixedBlocks = 0; + + _progressLogger.Reset(0, totalBlocks); + for (long blockNumber = startingBlock; blockNumber <= lastBlock; ++blockNumber) { cancellationToken.ThrowIfCancellationRequested(); @@ -75,6 +83,7 @@ private void RunMigration(long startingBlock, long? lastBlock, CancellationToken $"Found discrepancy in block {header.ToString(BlockHeader.Format.Short)} total difficulty: should be {expectedTd}, was {actualTd}. Fixing."); blockInfo.TotalDifficulty = expectedTd; shouldPersist = true; + fixedBlocks++; } } @@ -82,9 +91,23 @@ private void RunMigration(long startingBlock, long? lastBlock, CancellationToken { _chainLevelInfoRepository.PersistLevel(blockNumber, currentLevel); } + + processedBlocks++; + + // Update progress every 1000 blocks or when progress logger suggests + if (processedBlocks % 1000 == 0) + { + _progressLogger.Update(processedBlocks); + _progressLogger.LogProgress(); + } } - if (_logger.IsInfo) _logger.Info("Ended TotalDifficultyFixMigration."); + // Final progress update + _progressLogger.Update(processedBlocks); + _progressLogger.MarkEnd(); + _progressLogger.LogProgress(); + + if (_logger.IsInfo) _logger.Info($"Ended TotalDifficultyFixMigration. Processed {processedBlocks} blocks, fixed {fixedBlocks} blocks."); } UInt256? FindParentTd(BlockHeader blockHeader, long level) diff --git a/src/Nethermind/Nethermind.State.Test/StateReaderTests.cs b/src/Nethermind/Nethermind.State.Test/StateReaderTests.cs index 25100d48cce..393cab28047 100644 --- a/src/Nethermind/Nethermind.State.Test/StateReaderTests.cs +++ b/src/Nethermind/Nethermind.State.Test/StateReaderTests.cs @@ -262,7 +262,8 @@ public void Can_collect_stats() } IStateReader stateReader = worldStateManager.GlobalStateReader; - var stats = stateReader.CollectStats(stateRoot, new MemDb(), Logger); + ProgressLogger progressLogger = new ProgressLogger("Stats Collection", Logger); + var stats = stateReader.CollectStats(stateRoot, new MemDb(), Logger, progressLogger, default); stats.AccountCount.Should().Be(1); } @@ -401,7 +402,8 @@ public void Can_accepts_visitors() stateRoot = provider.StateRoot; } - TrieStatsCollector visitor = new(new MemDb(), LimboLogs.Instance); + ProgressLogger progressLogger = new ProgressLogger("Stats Collection", LimboLogs.Instance); + TrieStatsCollector visitor = new(new MemDb(), LimboLogs.Instance, progressLogger, default); worldStateManager.GlobalStateReader.RunTreeVisitor(visitor, stateRoot); } diff --git a/src/Nethermind/Nethermind.State.Test/StatsCollectorTests.cs b/src/Nethermind/Nethermind.State.Test/StatsCollectorTests.cs index 713304b13a8..07fedcafd34 100644 --- a/src/Nethermind/Nethermind.State.Test/StatsCollectorTests.cs +++ b/src/Nethermind/Nethermind.State.Test/StatsCollectorTests.cs @@ -61,7 +61,8 @@ public void Can_collect_stats([Values(false, true)] bool parallel) Hash256 storageKey = new("0x345e54154080bfa9e8f20c99d7a0139773926479bc59e5b4f830ad94b6425332"); nodeStorage.Set(address, path, storageKey, null); - TrieStatsCollector statsCollector = new(codeDb, LimboLogs.Instance); + ProgressLogger progressLogger = new ProgressLogger("Stats Collection", LimboLogs.Instance); + TrieStatsCollector statsCollector = new(codeDb, LimboLogs.Instance, progressLogger, default); VisitingOptions visitingOptions = new VisitingOptions() { MaxDegreeOfParallelism = parallel ? 0 : 1 diff --git a/src/Nethermind/Nethermind.State/BlockingVerifyTrie.cs b/src/Nethermind/Nethermind.State/BlockingVerifyTrie.cs index e7921cd9513..ecad692343b 100644 --- a/src/Nethermind/Nethermind.State/BlockingVerifyTrie.cs +++ b/src/Nethermind/Nethermind.State/BlockingVerifyTrie.cs @@ -18,11 +18,11 @@ namespace Nethermind.State; public class BlockingVerifyTrie { private readonly ILogger _logger; - private readonly ITrieStore _trieStore; private readonly IStateReader _stateReader; private readonly IDb _codeDb; private readonly ILogManager _logManager; + private readonly ProgressLogger _progressLogger; public BlockingVerifyTrie( ITrieStore trieStore, @@ -40,6 +40,7 @@ public BlockingVerifyTrie( _codeDb = codeDb; _logManager = logManager; _logger = logManager.GetClassLogger(); + _progressLogger = new ProgressLogger("Trie Verification", logManager); } public bool VerifyTrie(BlockHeader stateAtBlock, CancellationToken cancellationToken) @@ -48,7 +49,19 @@ public bool VerifyTrie(BlockHeader stateAtBlock, CancellationToken cancellationT using IDisposable _ = _trieStore.BeginScope(stateAtBlock); Hash256 rootNode = stateAtBlock.StateRoot; - TrieStats stats = _stateReader.CollectStats(rootNode, _codeDb, _logManager, cancellationToken); + + if (_logger.IsInfo) _logger.Info($"Starting trie verification for block {stateAtBlock.Number} with state root {rootNode}"); + + // Initialize progress logger + _progressLogger.Reset(0, 0); // We'll update as we go since we don't know total nodes upfront + + TrieStats stats = _stateReader.CollectStats(rootNode, _codeDb, _logManager, _progressLogger, cancellationToken); + + // Update progress logger with final stats + _progressLogger.Update(stats.NodesCount); + _progressLogger.MarkEnd(); + _progressLogger.LogProgress(); + if (stats.MissingNodes > 0) { if (_logger.IsError) _logger.Error($"Missing node found!"); diff --git a/src/Nethermind/Nethermind.State/StateReaderExtensions.cs b/src/Nethermind/Nethermind.State/StateReaderExtensions.cs index 933ec39162b..bf996145e0d 100644 --- a/src/Nethermind/Nethermind.State/StateReaderExtensions.cs +++ b/src/Nethermind/Nethermind.State/StateReaderExtensions.cs @@ -44,9 +44,9 @@ public static ValueHash256 GetCodeHash(this IStateReader stateReader, BlockHeade return account.CodeHash; } - public static TrieStats CollectStats(this IStateReader stateProvider, Hash256 root, IKeyValueStore codeStorage, ILogManager logManager, CancellationToken cancellationToken = default) + public static TrieStats CollectStats(this IStateReader stateProvider, Hash256 root, IKeyValueStore codeStorage, ILogManager logManager, ProgressLogger progressLogger, CancellationToken cancellationToken = default) { - TrieStatsCollector collector = new(codeStorage, logManager, cancellationToken); + TrieStatsCollector collector = new(codeStorage, logManager, progressLogger, cancellationToken); stateProvider.RunTreeVisitor(collector, root, new VisitingOptions { MaxDegreeOfParallelism = Environment.ProcessorCount, diff --git a/src/Nethermind/Nethermind.Synchronization.Test/FastSync/StateSyncFeedTestsBase.cs b/src/Nethermind/Nethermind.Synchronization.Test/FastSync/StateSyncFeedTestsBase.cs index e4cdc5e58db..cee4e350586 100644 --- a/src/Nethermind/Nethermind.Synchronization.Test/FastSync/StateSyncFeedTestsBase.cs +++ b/src/Nethermind/Nethermind.Synchronization.Test/FastSync/StateSyncFeedTestsBase.cs @@ -257,7 +257,8 @@ public void CompareTrees(string stage, bool skipLogs = false) if (stage == "END") { Assert.That(local, Is.EqualTo(remote), $"{stage}{Environment.NewLine}{remote}{Environment.NewLine}{local}"); - TrieStatsCollector collector = new(LocalCodeDb, LimboLogs.Instance); + ProgressLogger progressLogger = new ProgressLogger("Stats Collection", LimboLogs.Instance); + TrieStatsCollector collector = new(LocalCodeDb, LimboLogs.Instance, progressLogger, default); LocalStateTree.Accept(collector, LocalStateTree.RootHash); Assert.That(collector.Stats.MissingNodes, Is.EqualTo(0)); Assert.That(collector.Stats.MissingCode, Is.EqualTo(0)); diff --git a/src/Nethermind/Nethermind.Trie/TrieStatsCollector.cs b/src/Nethermind/Nethermind.Trie/TrieStatsCollector.cs index f799f5eb20b..4702d3c8b0a 100644 --- a/src/Nethermind/Nethermind.Trie/TrieStatsCollector.cs +++ b/src/Nethermind/Nethermind.Trie/TrieStatsCollector.cs @@ -15,6 +15,7 @@ public class TrieStatsCollector : ITreeVisitor private readonly ClockCache _existingCodeHash = new ClockCache(1024 * 8); private readonly IKeyValueStore _codeKeyValueStore; private long _lastAccountNodeCount = 0; + private readonly ProgressLogger _progressLogger; private readonly ILogger _logger; private readonly CancellationToken _cancellationToken; @@ -58,11 +59,12 @@ public readonly Context AddStorage(in ValueHash256 storage) } } - public TrieStatsCollector(IKeyValueStore codeKeyValueStore, ILogManager logManager, CancellationToken cancellationToken = default) + public TrieStatsCollector(IKeyValueStore codeKeyValueStore, ILogManager logManager, ProgressLogger progressLogger, CancellationToken cancellationToken = default) { _codeKeyValueStore = codeKeyValueStore ?? throw new ArgumentNullException(nameof(codeKeyValueStore)); _logger = logManager.GetClassLogger(); _cancellationToken = cancellationToken; + _progressLogger = progressLogger ?? throw new ArgumentNullException(nameof(progressLogger)); } public TrieStats Stats { get; } = new(); @@ -70,6 +72,7 @@ public TrieStatsCollector(IKeyValueStore codeKeyValueStore, ILogManager logManag public bool IsFullDbScan => true; public void VisitTree(in Context nodeContext, in ValueHash256 rootHash) { + _progressLogger.Reset(0, 0); // We'll update as we go since we don't know total nodes upfront } public bool ShouldVisit(in Context nodeContext, in ValueHash256 nextNode) @@ -131,9 +134,13 @@ public void VisitLeaf(in Context nodeContext, TrieNode node) { long lastAccountNodeCount = _lastAccountNodeCount; long currentNodeCount = Stats.NodesCount; + + _progressLogger.Update(currentNodeCount); + + // Log progress every 1 million nodes if (currentNodeCount - lastAccountNodeCount > 1_000_000 && Interlocked.CompareExchange(ref _lastAccountNodeCount, currentNodeCount, lastAccountNodeCount) == lastAccountNodeCount) { - _logger.Warn($"Collected info from {Stats.NodesCount} nodes. Missing CODE {Stats.MissingCode} STATE {Stats.MissingState} STORAGE {Stats.MissingStorage}"); + _progressLogger.LogProgress(); } if (nodeContext.IsStorage)