Add consistent progress bars for syncing (#7212)

NethermindEth · Jun 26, 2024 · 229bd6b · 229bd6b
1 parent 9a3bf39
commit 229bd6b
Show file tree

Hide file tree

Showing 9 changed files with 141 additions and 65 deletions.
diff --git a/src/Nethermind/Nethermind.Logging/Progress.cs b/src/Nethermind/Nethermind.Logging/Progress.cs
@@ -0,0 +1,35 @@
+// SPDX-FileCopyrightText: 2024 Demerzel Solutions Limited
+// SPDX-License-Identifier: LGPL-3.0-only
+
+using System;
+
+namespace Nethermind.Logging;
+public static class Progress
+{
+    private const int Width = 40;
+    private const int WidthBar = Width - 3;
+
+    private static readonly string[] _progressChars = [" ", "⡀", "⡄", "⡆", "⡇", "⣇", "⣧", "⣷", "⣿"];
+    private static readonly string[] _fullChunks = CreateChunks('⣿', "[", "");
+    private static readonly string[] _emptyChunks = CreateChunks(' ', "", "]");
+
+    private static string[] CreateChunks(char ch, string start, string end)
+    {
+        var chunks = new string[WidthBar + 1];
+        for (int i = 0; i < chunks.Length; i++)
+        {
+            chunks[i] = start + new string(ch, i) + end;
+        }
+
+        return chunks;
+    }
+
+    public static string GetMeter(float value, int max)
+    {
+        float progressF = value / max * WidthBar;
+        int progress = (int)Math.Floor(progressF);
+        int progressChar = (int)((progressF - progress) * _progressChars.Length);
+
+        return string.Concat(_fullChunks[progress], _progressChars[progressChar], _emptyChunks[WidthBar - progress - 1]);
+    }
+}
diff --git a/src/Nethermind/Nethermind.Merge.Plugin/Handlers/ForkchoiceUpdatedHandler.cs b/src/Nethermind/Nethermind.Merge.Plugin/Handlers/ForkchoiceUpdatedHandler.cs
@@ -189,7 +189,8 @@ public async Task<ResultWrapper<ForkchoiceUpdatedV1Result>> Handle(ForkchoiceSta
                 _blockCacheService.FinalizedHash = forkchoiceState.FinalizedBlockHash;
                 _mergeSyncController.StopBeaconModeControl();
 
-                if (_logger.IsInfo) _logger.Info($"Syncing beacon headers, Request: {requestStr}");
+                // Debug as already output in Received ForkChoice
+                if (_logger.IsDebug) _logger.Debug($"Syncing beacon headers, Request: {requestStr}");
             }
             else
             {

diff --git a/src/Nethermind/Nethermind.Runner/NLog.config b/src/Nethermind/Nethermind.Runner/NLog.config
@@ -49,7 +49,7 @@
       <highlight-word regex="(?&lt;=\| )(Rerunning|Allocated sync peers|Peers)" foregroundColor="DarkMagenta" wholeWords="true" />
       <highlight-word regex="(?&lt;=\| )(Downloaded|Reorged|Syncing|Processed)" foregroundColor="DarkCyan" wholeWords="true" />
       <!-- State change from -->
-      <highlight-word regex="(?&lt;=(from |state ))[a-zA-Z \,]+(?= to)" foregroundColor="DarkCyan" wholeWords="true" />
+      <highlight-word regex="(?&lt;=(from |sync ))[a-zA-Z \,]+(?= to)" foregroundColor="DarkCyan" wholeWords="true" />
       <!-- State change to -->
       <highlight-word regex="(?&lt;=to )(FastHeaders|FastSync|FastHeaders|SnapSync|\, )+" foregroundColor="DarkGreen" wholeWords="true" />
       <!-- Important notes -->
@@ -77,6 +77,8 @@
       <highlight-word regex="(sload|sstore|create|calls) +[0-9\,]+" foregroundColor="Gray" wholeWords="true" />
       <!-- Seperators (de-emphasize) -->
       <highlight-word regex=" \| " foregroundColor="Gray" wholeWords="true" />
+      <!-- Progress bar dark green -->
+      <highlight-word regex="(?&lt;=[\[])[ ⡀⡄⡆⡇⣇⣧⣷⣿]+(?=[\]])" foregroundColor="DarkGray" />
     </target>
 
     <!-- note: you need to specify `Seq.MinLevel` or this target will be removed. `Seq.ServerUrl` will always replace url here. -->

diff --git a/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs b/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs
@@ -101,15 +101,15 @@ public void Ancient_bodies_and_receipts_are_reported_correctly(
 
             if (setBarriers)
             {
-                iLogger.Received(1).Info("Old Headers    0 / 100 (  0.00 %) | queue         0 | current            0 Blk/s | total            0 Blk/s");
-                iLogger.Received(1).Info("Old Bodies     0 / 70 (  0.00 %) | queue         0 | current            0 Blk/s | total            0 Blk/s");
-                iLogger.Received(1).Info("Old Receipts   0 / 65 (  0.00 %) | queue         0 | current            0 Blk/s | total            0 Blk/s");
+                iLogger.Received(1).Info("Old Headers           0 /        100 (  0.00 %) [                                     ] queue        0 | current       0 Blk/s");
+                iLogger.Received(1).Info("Old Bodies            0 /         70 (  0.00 %) [                                     ] queue        0 | current       0 Blk/s");
+                iLogger.Received(1).Info("Old Receipts          0 /         65 (  0.00 %) [                                     ] queue        0 | current       0 Blk/s");
             }
             else
             {
-                iLogger.Received(1).Info("Old Headers    0 / 100 (  0.00 %) | queue         0 | current            0 Blk/s | total            0 Blk/s");
-                iLogger.Received(1).Info("Old Bodies     0 / 100 (  0.00 %) | queue         0 | current            0 Blk/s | total            0 Blk/s");
-                iLogger.Received(1).Info("Old Receipts   0 / 100 (  0.00 %) | queue         0 | current            0 Blk/s | total            0 Blk/s");
+                iLogger.Received(1).Info("Old Headers           0 /        100 (  0.00 %) [                                     ] queue        0 | current       0 Blk/s");
+                iLogger.Received(1).Info("Old Bodies            0 /        100 (  0.00 %) [                                     ] queue        0 | current       0 Blk/s");
+                iLogger.Received(1).Info("Old Receipts          0 /        100 (  0.00 %) [                                     ] queue        0 | current       0 Blk/s");
             }
         }
     }

diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/BranchProgress.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/BranchProgress.cs
@@ -21,6 +21,7 @@ internal class BranchProgress
     {
         private readonly ILogger _logger;
         private readonly NodeProgressState[] _syncProgress;
+        private long _lastReportMs = 0;
 
         public decimal LastProgress { get; private set; }
         public long CurrentSyncBlock { get; }
@@ -138,9 +139,15 @@ public void ReportSynced(int level, int parentIndex, int childIndex, NodeDataTyp
                 return;
             }
 
-            string detailsString = string.Empty;
-            if (_logger.IsInfo)
+            Progress = (decimal)savedBranches / _syncProgress.Length;
+
+            const long minMillisecondsBetweenReports = 10_000;
+
+            long reportTicksMs = Environment.TickCount64;
+            if (reportTicksMs - _lastReportMs >= minMillisecondsBetweenReports && _logger.IsInfo)
             {
+                _lastReportMs = reportTicksMs;
+
                 StringBuilder builder = new();
                 for (int i = 0; i < _syncProgress.Length; i++)
                 {
@@ -152,30 +159,27 @@ public void ReportSynced(int level, int parentIndex, int childIndex, NodeDataTyp
                     switch (_syncProgress[i])
                     {
                         case NodeProgressState.Unknown:
-                            builder.Append('?');
+                            builder.Append('▫');
                             break;
                         case NodeProgressState.Empty:
-                            builder.Append('0');
+                            builder.Append('◇');
                             break;
                         case NodeProgressState.AlreadySaved:
-                            builder.Append('1');
+                            builder.Append('◆');
                             break;
                         case NodeProgressState.Saved:
-                            builder.Append('+');
+                            builder.Append('■');
                             break;
                         case NodeProgressState.Requested:
-                            builder.Append('*');
+                            builder.Append('□');
                             break;
                         default:
                             throw new ArgumentOutOfRangeException();
                     }
                 }
 
-                detailsString = builder.ToString();
+                _logger.Info($"Branch sync progress (do not extrapolate): {Progress:p2} of block {CurrentSyncBlock}{builder}");
             }
-
-            Progress = (decimal)savedBranches / _syncProgress.Length;
-            if (_logger.IsInfo) _logger.Info($"Branch sync progress (do not extrapolate): {Progress:p2} of block {CurrentSyncBlock}{detailsString}");
         }
 
         public decimal Progress { get; set; }

diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs
@@ -39,6 +39,8 @@ public class DetailedProgress
         internal long NotAssignedCount;
         internal long DataSize;
 
+        private string? _lastStateSyncReport;
+
         private long TotalRequestsCount => EmptishCount + InvalidFormatCount + BadQualityCount + OkCount + NotAssignedCount;
         public long ProcessedRequestsCount => EmptishCount + BadQualityCount + OkCount;
 
@@ -69,17 +71,26 @@ internal void DisplayProgressReport(int pendingRequestsCount, BranchProgress bra
                 // if (_logger.IsInfo) _logger.Info($"Time {TimeSpan.FromSeconds(_secondsInSync):dd\\.hh\\:mm\\:ss} | {(decimal) _dataSize / 1000 / 1000,6:F2}MB | kBps: {savedKBytesPerSecond,5:F0} | P: {_pendingRequests.Count} | acc {_savedAccounts} | queues {StreamsDescription} | db {_averageTimeInHandler:f2}ms");
 
                 Metrics.StateSynced = DataSize;
-                string dataSizeInfo = $"{(decimal)DataSize / 1000 / 1000,6:F2} MB";
+                string dataSizeInfo = $"{(decimal)DataSize / 1000 / 1000,9:F2} MB";
                 if (_chainEstimations.StateSize is not null)
                 {
-                    decimal percentage = Math.Min(1, (decimal)DataSize / _chainEstimations.StateSize.Value);
-                    dataSizeInfo = string.Concat(
-                        $"~{percentage:P2} | ", dataSizeInfo,
-                        $" / ~{(decimal)_chainEstimations.StateSize.Value / 1000 / 1000,6:F2} MB");
+                    float percentage = Math.Min(1, (float)DataSize / _chainEstimations.StateSize.Value);
+                    dataSizeInfo = string.Concat(dataSizeInfo,
+                        $" / {(decimal)_chainEstimations.StateSize.Value / 1000 / 1000,6:F0} MB",
+                        $" ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)}");
                 }
 
-                if (logger.IsInfo) logger.Info(
-                    $"State Sync {TimeSpan.FromSeconds(SecondsInSync):dd\\.hh\\:mm\\:ss} | {dataSizeInfo} | branches: {branchProgress.Progress:P2} | kB/s: {savedKBytesPerSecond,5:F0} | accounts {SavedAccounts} | nodes {SavedNodesCount} | pending: {pendingRequestsCount,3} | ave: {AverageTimeInHandler:f2}ms");
+                if (logger.IsInfo)
+                {
+                    string stateSyncReport = logger.IsDebug ?
+                        $"State Sync  {dataSizeInfo} branches: {branchProgress.Progress:P2} | kB/s: {savedKBytesPerSecond,5:F0} | accounts {SavedAccounts} | nodes {SavedNodesCount} | pending: {pendingRequestsCount,3}" :
+                        $"State Sync  {dataSizeInfo} branch {branchProgress.Progress:P2} | acc {SavedAccounts} | nodes {SavedNodesCount}";
+                    if (_lastStateSyncReport != stateSyncReport)
+                    {
+                        _lastStateSyncReport = stateSyncReport;
+                        logger.Info(stateSyncReport);
+                    }
+                }
                 if (logger.IsDebug && DateTime.UtcNow - LastReportTime.full > TimeSpan.FromSeconds(10))
                 {
                     long allChecks = CheckWasInDependencies + CheckWasCached + StateWasThere + StateWasNotThere;

diff --git a/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs b/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs
@@ -223,7 +223,7 @@ public void Update()
                             if (IsTheModeSwitchWorthMentioning(current, newModes))
                             {
                                 if (_logger.IsInfo)
-                                    _logger.Info($"Changing state {current} to {newModes} at {BuildStateString(best)}");
+                                    _logger.Info($"Changing sync {current} to {newModes} at {BuildStateString(best)}");
                             }
                         }
                         catch (InvalidAsynchronousStateException)
@@ -288,8 +288,9 @@ private void UpdateSyncModes(SyncMode newModes, string? reason = null)
         /// </summary>
         /// <param name="best">Snapshot of the best known states</param>
         /// <returns>A string describing the state of sync</returns>
-        private static string BuildStateString(Snapshot best) =>
-            $"processed: {best.Processed} | state: {best.State} | block: {best.Block} | header: {best.Header} | target block: {best.TargetBlock} | peer block: {best.Peer.Block}";
+        private static string BuildStateString(Snapshot best) => best.Block == best.Header ?
+            $"block: {best.Block} | target: {best.TargetBlock} | peer: {best.Peer.Block}" :
+            $"block: {best.Block} | header: {best.Header} | target: {best.TargetBlock} | peer: {best.Peer.Block}";
 
         private static string BuildStateStringDebug(Snapshot best) =>
             $"processed: {best.Processed} | state: {best.State} | block: {best.Block} | header: {best.Header} | chain difficulty: {best.ChainDifficulty} | target block: {best.TargetBlock} | peer block: {best.Peer.Block} | peer total difficulty: {best.Peer.TotalDifficulty}";