From 6f3072103cd049e3c8bed4e2fdc08bef4e8c2502 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 07:18:52 +0100 Subject: [PATCH 01/21] Add progress bars for syncing --- src/Nethermind/Nethermind.Logging/Progress.cs | 20 +++++++++++++++++++ .../FastSync/BranchProgress.cs | 10 +++++----- .../Reporting/SyncReport.cs | 15 +++++++++----- .../SnapSync/ProgressTracker.cs | 2 +- 4 files changed, 36 insertions(+), 11 deletions(-) create mode 100644 src/Nethermind/Nethermind.Logging/Progress.cs diff --git a/src/Nethermind/Nethermind.Logging/Progress.cs b/src/Nethermind/Nethermind.Logging/Progress.cs new file mode 100644 index 00000000000..9789e305d52 --- /dev/null +++ b/src/Nethermind/Nethermind.Logging/Progress.cs @@ -0,0 +1,20 @@ +// SPDX-FileCopyrightText: 2024 Demerzel Solutions Limited +// SPDX-License-Identifier: LGPL-3.0-only + +using System; + +namespace Nethermind.Logging; +public class Progress +{ + private static char[] _progressChars = { ' ', '⡀', '⡄', '⡆', '⡇', '⣇', '⣧', '⣷', '⣿' }; + + public static string GetMeter(float value, int max, int width = 20) + { + width = Math.Max(4, width - 3); + float progressF = value / max * width; + int progress = (int)Math.Floor(progressF); + int progressChar = (int)((progressF - progress) * _progressChars.Length); + + return $"[{new string('⣿', progress)}{_progressChars[progressChar]}{new string(' ', width - progress - 1)}]"; + } +} diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/BranchProgress.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/BranchProgress.cs index 7d804204ed6..103e2b85c42 100644 --- a/src/Nethermind/Nethermind.Synchronization/FastSync/BranchProgress.cs +++ b/src/Nethermind/Nethermind.Synchronization/FastSync/BranchProgress.cs @@ -152,19 +152,19 @@ 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(); diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index f088c7b1430..b526ded1cc7 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -15,7 +15,8 @@ namespace Nethermind.Synchronization.Reporting { public class SyncReport : ISyncReport { - private const int SpeedPaddingLength = 9; + private const int SpeedPaddingLength = 6; + private const int ProgressLength = 40; private readonly ISyncPeerPool _syncPeerPool; private readonly ISyncConfig _syncConfig; @@ -290,7 +291,8 @@ private void WriteFullSyncReport() return; } - _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1),8:P2}) | current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s | total {Pad(FullSyncBlocksDownloaded.TotalPerSecond, SpeedPaddingLength)} Blk/s"); + var percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); + _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FullSyncBlocksDownloaded.SetMeasuringPoint(); } @@ -298,19 +300,22 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) { if ((currentSyncMode & SyncMode.FastHeaders) == SyncMode.FastHeaders) { - _logger.Info($"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1),8:P2}) | queue {Pad(HeadersInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s | total {Pad(FastBlocksHeaders.TotalPerSecond, SpeedPaddingLength)} Blk/s"); + var percentage = Math.Clamp(FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1), 0, 1); + _logger.Info($"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(HeadersInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FastBlocksHeaders.SetMeasuringPoint(); } if ((currentSyncMode & SyncMode.FastBodies) == SyncMode.FastBodies) { - _logger.Info($"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1),8:P2}) | queue {Pad(BodiesInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s | total {Pad(FastBlocksBodies.TotalPerSecond, SpeedPaddingLength)} Blk/s"); + var percentage = Math.Clamp(FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1), 0, 1); + _logger.Info($"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(BodiesInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FastBlocksBodies.SetMeasuringPoint(); } if ((currentSyncMode & SyncMode.FastReceipts) == SyncMode.FastReceipts) { - _logger.Info($"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1),8:P2}) | queue {Pad(ReceiptsInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s | total {Pad(FastBlocksReceipts.TotalPerSecond, SpeedPaddingLength)} Blk/s"); + var percentage = Math.Clamp(FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1), 0, 1); + _logger.Info($"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(ReceiptsInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FastBlocksReceipts.SetMeasuringPoint(); } } diff --git a/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs b/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs index 4e0f9722f80..fc53bb359f0 100644 --- a/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs +++ b/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs @@ -421,7 +421,7 @@ private void LogRequest(string reqType) float progress = (float)(totalPathProgress / (double)(256 * 256)); - if (_logger.IsInfo) _logger.Info($"Snap State Ranges (Phase 1): ({progress,8:P2}) [{new string('*', (int)(progress * 71))}{new string(' ', 71 - (int)(progress * 71))}]"); + if (_logger.IsInfo) _logger.Info($"Snap State Ranges (Phase 1): ({progress,8:P2}) {Progress.GetMeter(progress, 1, 40)}"); } if (_logger.IsTrace || _reqCount % 1000 == 0) From 33ad37713f2f63de9881c5ed9b31e3a75e7f4bc5 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 07:33:43 +0100 Subject: [PATCH 02/21] Tests --- .../SyncReportTest.cs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs b/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs index 074cb71ee56..8a2e5d28ef9 100644 --- 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"); } } } From 87c367c625b7aa9e0881b254bc38813c653a3d09 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 08:10:14 +0100 Subject: [PATCH 03/21] Adjust spacing --- .../SyncReportTest.cs | 12 ++++++------ .../Reporting/SyncReport.cs | 13 +++++++------ 2 files changed, 13 insertions(+), 12 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs b/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs index 8a2e5d28ef9..0601d55237e 100644 --- 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"); - 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"); + 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"); - 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"); + 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/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index b526ded1cc7..94ec9a4962e 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -15,7 +15,8 @@ namespace Nethermind.Synchronization.Reporting { public class SyncReport : ISyncReport { - private const int SpeedPaddingLength = 6; + private const int QueuePaddingLength = 7; + private const int SpeedPaddingLength = 5; private const int ProgressLength = 40; private readonly ISyncPeerPool _syncPeerPool; @@ -292,7 +293,7 @@ private void WriteFullSyncReport() } var percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); - _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, QueuePaddingLength)} current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FullSyncBlocksDownloaded.SetMeasuringPoint(); } @@ -301,21 +302,21 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) if ((currentSyncMode & SyncMode.FastHeaders) == SyncMode.FastHeaders) { var percentage = Math.Clamp(FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1), 0, 1); - _logger.Info($"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(HeadersInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(HeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FastBlocksHeaders.SetMeasuringPoint(); } if ((currentSyncMode & SyncMode.FastBodies) == SyncMode.FastBodies) { var percentage = Math.Clamp(FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1), 0, 1); - _logger.Info($"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(BodiesInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(BodiesInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FastBlocksBodies.SetMeasuringPoint(); } if ((currentSyncMode & SyncMode.FastReceipts) == SyncMode.FastReceipts) { var percentage = Math.Clamp(FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1), 0, 1); - _logger.Info($"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(ReceiptsInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(ReceiptsInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FastBlocksReceipts.SetMeasuringPoint(); } } @@ -325,7 +326,7 @@ private void WriteBeaconSyncReport() long numHeadersToDownload = _pivot.PivotNumber - _pivot.PivotDestinationNumber + 1; int paddingLength = numHeadersToDownload.ToString("N0").Length; _logger.Info($"Beacon Headers from block {_pivot.PivotDestinationNumber} to block {_pivot.PivotNumber} | " - + $"{Pad(BeaconHeaders.CurrentValue, paddingLength)} / {Pad(numHeadersToDownload, paddingLength)} | queue {Pad(BeaconHeadersInQueue.CurrentValue, SpeedPaddingLength)} | current {Pad(BeaconHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s | total {Pad(BeaconHeaders.TotalPerSecond, SpeedPaddingLength)} Blk/s"); + + $"{Pad(BeaconHeaders.CurrentValue, paddingLength)} / {Pad(numHeadersToDownload, paddingLength)} | queue {Pad(BeaconHeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(BeaconHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s | total {Pad(BeaconHeaders.TotalPerSecond, SpeedPaddingLength)} Blk/s"); BeaconHeaders.SetMeasuringPoint(); } From 63075ff5af1480c1b67197f7686c828ac77d4087 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 08:14:18 +0100 Subject: [PATCH 04/21] Wrong change --- .../Nethermind.Synchronization/Reporting/SyncReport.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index 94ec9a4962e..ef4f88a63a3 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -293,7 +293,7 @@ private void WriteFullSyncReport() } var percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); - _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, QueuePaddingLength)} current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FullSyncBlocksDownloaded.SetMeasuringPoint(); } From 48ac97ccc7087f54e3afca9e76e580d43fedd753 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 09:29:08 +0100 Subject: [PATCH 05/21] Also state sync --- src/Nethermind/Nethermind.Logging/Progress.cs | 2 +- .../FastSync/DetailedProgress.cs | 12 ++++++------ .../Reporting/SyncReport.cs | 9 ++++----- .../SnapSync/ProgressTracker.cs | 2 +- 4 files changed, 12 insertions(+), 13 deletions(-) diff --git a/src/Nethermind/Nethermind.Logging/Progress.cs b/src/Nethermind/Nethermind.Logging/Progress.cs index 9789e305d52..7754685a4c2 100644 --- a/src/Nethermind/Nethermind.Logging/Progress.cs +++ b/src/Nethermind/Nethermind.Logging/Progress.cs @@ -8,7 +8,7 @@ public class Progress { private static char[] _progressChars = { ' ', '⡀', '⡄', '⡆', '⡇', '⣇', '⣧', '⣷', '⣿' }; - public static string GetMeter(float value, int max, int width = 20) + public static string GetMeter(float value, int max, int width = 40) { width = Math.Max(4, width - 3); float progressF = value / max * width; diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs index 669ec926fa4..9dea6e1d60f 100644 --- a/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs +++ b/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs @@ -69,17 +69,17 @@ 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"); + $"State Sync {dataSizeInfo} branches: {branchProgress.Progress:P2} | kB/s: {savedKBytesPerSecond,5:F0} | accounts {SavedAccounts} | nodes {SavedNodesCount} | pending: {pendingRequestsCount,3}"); if (logger.IsDebug && DateTime.UtcNow - LastReportTime.full > TimeSpan.FromSeconds(10)) { long allChecks = CheckWasInDependencies + CheckWasCached + StateWasThere + StateWasNotThere; diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index ef4f88a63a3..8092cf47790 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -17,7 +17,6 @@ public class SyncReport : ISyncReport { private const int QueuePaddingLength = 7; private const int SpeedPaddingLength = 5; - private const int ProgressLength = 40; private readonly ISyncPeerPool _syncPeerPool; private readonly ISyncConfig _syncConfig; @@ -293,7 +292,7 @@ private void WriteFullSyncReport() } var percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); - _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FullSyncBlocksDownloaded.SetMeasuringPoint(); } @@ -302,21 +301,21 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) if ((currentSyncMode & SyncMode.FastHeaders) == SyncMode.FastHeaders) { var percentage = Math.Clamp(FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1), 0, 1); - _logger.Info($"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(HeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(HeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FastBlocksHeaders.SetMeasuringPoint(); } if ((currentSyncMode & SyncMode.FastBodies) == SyncMode.FastBodies) { var percentage = Math.Clamp(FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1), 0, 1); - _logger.Info($"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(BodiesInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(BodiesInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FastBlocksBodies.SetMeasuringPoint(); } if ((currentSyncMode & SyncMode.FastReceipts) == SyncMode.FastReceipts) { var percentage = Math.Clamp(FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1), 0, 1); - _logger.Info($"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1, ProgressLength)} queue {Pad(ReceiptsInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(ReceiptsInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FastBlocksReceipts.SetMeasuringPoint(); } } diff --git a/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs b/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs index fc53bb359f0..84f47a23a18 100644 --- a/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs +++ b/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs @@ -421,7 +421,7 @@ private void LogRequest(string reqType) float progress = (float)(totalPathProgress / (double)(256 * 256)); - if (_logger.IsInfo) _logger.Info($"Snap State Ranges (Phase 1): ({progress,8:P2}) {Progress.GetMeter(progress, 1, 40)}"); + if (_logger.IsInfo) _logger.Info($"Snap State Ranges (Phase 1): ({progress,8:P2}) {Progress.GetMeter(progress, 1)}"); } if (_logger.IsTrace || _reqCount % 1000 == 0) From 40c6ff715163697bf1ea30e32661e59e60183160 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 09:30:16 +0100 Subject: [PATCH 06/21] formatting --- .../Nethermind.Synchronization/FastSync/DetailedProgress.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs index 9dea6e1d60f..a9601fdd006 100644 --- a/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs +++ b/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs @@ -74,8 +74,8 @@ internal void DisplayProgressReport(int pendingRequestsCount, BranchProgress bra { 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)}" ); + $" / {(decimal)_chainEstimations.StateSize.Value / 1000 / 1000,6:F0} MB", + $" ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)}"); } if (logger.IsInfo) logger.Info( From 32926cc49473a67ffd77c5ca70ab76e004a62ac4 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 10:35:59 +0100 Subject: [PATCH 07/21] Only output branch sync once very 10 secs --- .../FastSync/BranchProgress.cs | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/BranchProgress.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/BranchProgress.cs index 103e2b85c42..d8e78b82ecd 100644 --- 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++) { @@ -171,11 +178,8 @@ public void ReportSynced(int level, int parentIndex, int childIndex, NodeDataTyp } } - 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; } From 863a0011b5d0acbda96ad4e7d8032a67c97be6b1 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 11:15:51 +0100 Subject: [PATCH 08/21] Don't repeat same log during syncing --- .../FastSync/DetailedProgress.cs | 13 ++++++-- .../Reporting/SyncReport.cs | 32 +++++++++++++++---- .../SnapSync/ProgressTracker.cs | 11 ++++++- 3 files changed, 46 insertions(+), 10 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs index a9601fdd006..393fa29c78d 100644 --- 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; @@ -78,8 +80,15 @@ internal void DisplayProgressReport(int pendingRequestsCount, BranchProgress bra $" ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)}"); } - if (logger.IsInfo) logger.Info( - $"State Sync {dataSizeInfo} branches: {branchProgress.Progress:P2} | kB/s: {savedKBytesPerSecond,5:F0} | accounts {SavedAccounts} | nodes {SavedNodesCount} | pending: {pendingRequestsCount,3}"); + if (logger.IsInfo) + { + string stateSyncReport = $"State Sync {dataSizeInfo} branches: {branchProgress.Progress:P2} | kB/s: {savedKBytesPerSecond,5:F0} | accounts {SavedAccounts} | nodes {SavedNodesCount} | pending: {pendingRequestsCount,3}"; + 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/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index 8092cf47790..a566c87bdf6 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -95,6 +95,9 @@ private void TimerOnElapsed(object? sender, EventArgs e) private readonly ITimer _timer; private long _fastBlocksPivotNumber; + private string? _lastHeadersReport; + private string? _lastBodiesReport; + private string? _lastReceiptsReport; public MeasuredProgress HeadersInQueue { get; } = new(); @@ -291,7 +294,7 @@ private void WriteFullSyncReport() return; } - var percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); + float percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FullSyncBlocksDownloaded.SetMeasuringPoint(); } @@ -300,22 +303,37 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) { if ((currentSyncMode & SyncMode.FastHeaders) == SyncMode.FastHeaders) { - var percentage = Math.Clamp(FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1), 0, 1); - _logger.Info($"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(HeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + float percentage = Math.Clamp(FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1), 0, 1); + string headersReport = $"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(HeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; + if (_lastHeadersReport != headersReport) + { + _lastHeadersReport = headersReport; + _logger.Info(headersReport); + } FastBlocksHeaders.SetMeasuringPoint(); } if ((currentSyncMode & SyncMode.FastBodies) == SyncMode.FastBodies) { - var percentage = Math.Clamp(FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1), 0, 1); - _logger.Info($"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(BodiesInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + float percentage = Math.Clamp(FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1), 0, 1); + string bodiesReport = $"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(BodiesInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; + if (_lastBodiesReport != bodiesReport) + { + _lastBodiesReport = bodiesReport; + _logger.Info(bodiesReport); + } FastBlocksBodies.SetMeasuringPoint(); } if ((currentSyncMode & SyncMode.FastReceipts) == SyncMode.FastReceipts) { - var percentage = Math.Clamp(FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1), 0, 1); - _logger.Info($"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(ReceiptsInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + float percentage = Math.Clamp(FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1), 0, 1); + string receiptsReport = $"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(ReceiptsInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; + if (_lastReceiptsReport != receiptsReport) + { + _lastReceiptsReport = receiptsReport; + _logger.Info(receiptsReport); + } FastBlocksReceipts.SetMeasuringPoint(); } } diff --git a/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs b/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs index 84f47a23a18..bcc245120de 100644 --- a/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs +++ b/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs @@ -41,6 +41,7 @@ public class ProgressTracker : IDisposable private readonly ILogger _logger; private readonly IDb _db; + string? _lastStateRangesReport; // Partitions are indexed by its limit keccak/address as they are keep in the request struct and remain the same // throughout the sync. So its easy. @@ -421,7 +422,15 @@ private void LogRequest(string reqType) float progress = (float)(totalPathProgress / (double)(256 * 256)); - if (_logger.IsInfo) _logger.Info($"Snap State Ranges (Phase 1): ({progress,8:P2}) {Progress.GetMeter(progress, 1)}"); + if (_logger.IsInfo) + { + string stateRangesReport = $"Snap State Ranges (Phase 1): ({progress,8:P2}) {Progress.GetMeter(progress, 1)}"; + if (_lastStateRangesReport != stateRangesReport) + { + _logger.Info(stateRangesReport); + _lastStateRangesReport = stateRangesReport; + } + } } if (_logger.IsTrace || _reqCount % 1000 == 0) From 1f148e98d3993257c6bf86d1cd5db055358bef1e Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 11:21:22 +0100 Subject: [PATCH 09/21] Align Downloaded better --- .../Nethermind.Synchronization/Reporting/SyncReport.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index a566c87bdf6..d2d10ba2e40 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -295,7 +295,7 @@ private void WriteFullSyncReport() } float percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); - _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} | current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); FullSyncBlocksDownloaded.SetMeasuringPoint(); } From 4bbb7873111f4be3abe30812ace3ed9665dc823c Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 11:41:11 +0100 Subject: [PATCH 10/21] Don't include speed changes in log comparisons --- .../Reporting/SyncReport.cs | 18 ++++++++++++++---- 1 file changed, 14 insertions(+), 4 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index d2d10ba2e40..796abd7f101 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -95,6 +95,7 @@ private void TimerOnElapsed(object? sender, EventArgs e) private readonly ITimer _timer; private long _fastBlocksPivotNumber; + private string? _lastDownloadReport; private string? _lastHeadersReport; private string? _lastBodiesReport; private string? _lastReceiptsReport; @@ -295,7 +296,13 @@ private void WriteFullSyncReport() } float percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); - _logger.Info($"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} | current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"); + string downloadReport = $"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} | current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; + // Compare ignoring speed change + if (_lastDownloadReport.AsSpan().StartsWith(downloadReport.AsSpan(0, downloadReport.LastIndexOf("| current")))) + { + _lastDownloadReport = downloadReport; + _logger.Info(downloadReport); + } FullSyncBlocksDownloaded.SetMeasuringPoint(); } @@ -305,7 +312,8 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) { float percentage = Math.Clamp(FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1), 0, 1); string headersReport = $"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(HeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; - if (_lastHeadersReport != headersReport) + // Compare ignoring speed change + if (_lastHeadersReport.AsSpan().StartsWith(headersReport.AsSpan(0, headersReport.LastIndexOf("| current")))) { _lastHeadersReport = headersReport; _logger.Info(headersReport); @@ -317,7 +325,8 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) { float percentage = Math.Clamp(FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1), 0, 1); string bodiesReport = $"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(BodiesInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; - if (_lastBodiesReport != bodiesReport) + // Compare ignoring speed change + if (_lastBodiesReport.AsSpan().StartsWith(bodiesReport.AsSpan(0, bodiesReport.LastIndexOf("| current")))) { _lastBodiesReport = bodiesReport; _logger.Info(bodiesReport); @@ -329,7 +338,8 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) { float percentage = Math.Clamp(FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1), 0, 1); string receiptsReport = $"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(ReceiptsInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; - if (_lastReceiptsReport != receiptsReport) + // Compare ignoring speed change + if (_lastReceiptsReport.AsSpan().StartsWith(receiptsReport.AsSpan(0, receiptsReport.LastIndexOf("| current")))) { _lastReceiptsReport = receiptsReport; _logger.Info(receiptsReport); From d59a6c801e11cc3352201b1d16e468388aaba215 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 11:42:13 +0100 Subject: [PATCH 11/21] Invert --- .../Nethermind.Synchronization/Reporting/SyncReport.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index 796abd7f101..2bf7eade163 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -298,7 +298,7 @@ private void WriteFullSyncReport() float percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); string downloadReport = $"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} | current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; // Compare ignoring speed change - if (_lastDownloadReport.AsSpan().StartsWith(downloadReport.AsSpan(0, downloadReport.LastIndexOf("| current")))) + if (!_lastDownloadReport.AsSpan().StartsWith(downloadReport.AsSpan(0, downloadReport.LastIndexOf("| current")))) { _lastDownloadReport = downloadReport; _logger.Info(downloadReport); @@ -313,7 +313,7 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) float percentage = Math.Clamp(FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1), 0, 1); string headersReport = $"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(HeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; // Compare ignoring speed change - if (_lastHeadersReport.AsSpan().StartsWith(headersReport.AsSpan(0, headersReport.LastIndexOf("| current")))) + if (!_lastHeadersReport.AsSpan().StartsWith(headersReport.AsSpan(0, headersReport.LastIndexOf("| current")))) { _lastHeadersReport = headersReport; _logger.Info(headersReport); @@ -326,7 +326,7 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) float percentage = Math.Clamp(FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1), 0, 1); string bodiesReport = $"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(BodiesInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; // Compare ignoring speed change - if (_lastBodiesReport.AsSpan().StartsWith(bodiesReport.AsSpan(0, bodiesReport.LastIndexOf("| current")))) + if (!_lastBodiesReport.AsSpan().StartsWith(bodiesReport.AsSpan(0, bodiesReport.LastIndexOf("| current")))) { _lastBodiesReport = bodiesReport; _logger.Info(bodiesReport); @@ -339,7 +339,7 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) float percentage = Math.Clamp(FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1), 0, 1); string receiptsReport = $"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(ReceiptsInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; // Compare ignoring speed change - if (_lastReceiptsReport.AsSpan().StartsWith(receiptsReport.AsSpan(0, receiptsReport.LastIndexOf("| current")))) + if (!_lastReceiptsReport.AsSpan().StartsWith(receiptsReport.AsSpan(0, receiptsReport.LastIndexOf("| current")))) { _lastReceiptsReport = receiptsReport; _logger.Info(receiptsReport); From c65cfa283de0dc246b7e4cc02b7359cbb1e05c96 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 12:02:50 +0100 Subject: [PATCH 12/21] Less spammy sync changes --- src/Nethermind/Nethermind.Runner/NLog.config | 2 +- .../ParallelSync/MultiSyncModeSelector.cs | 4 ++-- .../Nethermind.Synchronization/Reporting/SyncReport.cs | 3 ++- 3 files changed, 5 insertions(+), 4 deletions(-) diff --git a/src/Nethermind/Nethermind.Runner/NLog.config b/src/Nethermind/Nethermind.Runner/NLog.config index 01f4f050a8f..92088881c18 100644 --- a/src/Nethermind/Nethermind.Runner/NLog.config +++ b/src/Nethermind/Nethermind.Runner/NLog.config @@ -49,7 +49,7 @@ - + diff --git a/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs b/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs index c33e126b4f3..19774103f32 100644 --- 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) @@ -289,7 +289,7 @@ private void UpdateSyncModes(SyncMode newModes, string? reason = null) /// Snapshot of the best known states /// A string describing the state of sync 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}"; + $"block: {best.Block} | header: {best.Header} | target: {best.TargetBlock} | peer: {best.Peer.Block} | processed: {best.Processed} | state: {best.State}"; 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}"; diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index 2bf7eade163..9b677dabe68 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -65,7 +65,8 @@ public void SyncModeSelectorOnChanged(object? sender, SyncModeChangedEventArgs e if (e.Previous != e.Current) { - if (_logger.IsInfo) _logger.Info($"Sync mode changed from {e.Previous} to {e.Current}"); + // Repeat of "Changing state" so only output as confirm in debug + if (_logger.IsDebug) _logger.Debug($"Sync mode changed from {e.Previous} to {e.Current}"); } } From b43744c0d98036a7a94ecabc8b5d88b1f866ead7 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 12:11:30 +0100 Subject: [PATCH 13/21] Shorter line --- .../ParallelSync/MultiSyncModeSelector.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs b/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs index 19774103f32..fcf89bd8464 100644 --- a/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs +++ b/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs @@ -289,7 +289,7 @@ private void UpdateSyncModes(SyncMode newModes, string? reason = null) /// Snapshot of the best known states /// A string describing the state of sync private static string BuildStateString(Snapshot best) => - $"block: {best.Block} | header: {best.Header} | target: {best.TargetBlock} | peer: {best.Peer.Block} | processed: {best.Processed} | state: {best.State}"; + $"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}"; From 314690475a604bd422e96e4556c52783a39cb954 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 12:29:24 +0100 Subject: [PATCH 14/21] Less spammy --- .../Handlers/ForkchoiceUpdatedHandler.cs | 3 ++- .../ParallelSync/MultiSyncModeSelector.cs | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/src/Nethermind/Nethermind.Merge.Plugin/Handlers/ForkchoiceUpdatedHandler.cs b/src/Nethermind/Nethermind.Merge.Plugin/Handlers/ForkchoiceUpdatedHandler.cs index 94df1f54b71..9bc80436b92 100644 --- 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> 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.Synchronization/ParallelSync/MultiSyncModeSelector.cs b/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs index fcf89bd8464..93adba6edba 100644 --- a/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs +++ b/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs @@ -288,7 +288,8 @@ private void UpdateSyncModes(SyncMode newModes, string? reason = null) /// /// Snapshot of the best known states /// A string describing the state of sync - private static string BuildStateString(Snapshot best) => + 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) => From a4eb787d760b582025780e24a5ea67e366a4b64f Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 12:32:53 +0100 Subject: [PATCH 15/21] formatting --- .../ParallelSync/MultiSyncModeSelector.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs b/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs index 93adba6edba..e9eff01f553 100644 --- a/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs +++ b/src/Nethermind/Nethermind.Synchronization/ParallelSync/MultiSyncModeSelector.cs @@ -289,7 +289,7 @@ private void UpdateSyncModes(SyncMode newModes, string? reason = null) /// Snapshot of the best known states /// A string describing the state of sync private static string BuildStateString(Snapshot best) => best.Block == best.Header ? - $"block: {best.Block} | target: {best.TargetBlock} | peer: {best.Peer.Block}": + $"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) => From f1cb3bbc00c547dd267ab3ffd603d4351974c748 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 12:35:37 +0100 Subject: [PATCH 16/21] Less spammy --- .../Nethermind.Synchronization/SnapSync/ProgressTracker.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs b/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs index bcc245120de..eda6709e66e 100644 --- a/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs +++ b/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs @@ -433,11 +433,11 @@ private void LogRequest(string reqType) } } - if (_logger.IsTrace || _reqCount % 1000 == 0) + if (_logger.IsTrace || (_logger.IsDebug && _reqCount % 1000 == 0)) { int moreAccountCount = AccountRangePartitions.Count(kv => kv.Value.MoreAccountsToRight); - _logger.Info( + _logger.Debug( $"Snap - ({reqType}, diff: {_pivot.Diff}) {moreAccountCount} - Requests Account: {_activeAccountRequests} | Storage: {_activeStorageRequests} | Code: {_activeCodeRequests} | Refresh: {_activeAccRefreshRequests} - Queues Slots: {NextSlotRange.Count} | Storages: {StoragesToRetrieve.Count} | Codes: {CodesToRetrieve.Count} | Refresh: {AccountsToRefresh.Count}"); } } From aa0d46a7d41f97506b97cf4f006523505639a69b Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 13:31:00 +0100 Subject: [PATCH 17/21] Use runtime padding --- .../SyncReportTest.cs | 12 +++--- .../Reporting/SyncReport.cs | 37 ++++++------------- 2 files changed, 17 insertions(+), 32 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs b/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs index 0601d55237e..45031ebfe13 100644 --- 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"); - 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"); + 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"); - 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"); + 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/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index 9b677dabe68..eb637c6d9ea 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -15,8 +15,9 @@ namespace Nethermind.Synchronization.Reporting { public class SyncReport : ISyncReport { - private const int QueuePaddingLength = 7; - private const int SpeedPaddingLength = 5; + private const int QueuePaddingLength = 8; + private const int SpeedPaddingLength = 7; + private const int BlockPaddingLength = 10; private readonly ISyncPeerPool _syncPeerPool; private readonly ISyncConfig _syncConfig; @@ -33,7 +34,6 @@ public class SyncReport : ISyncReport private const int SyncFullPeersReportFrequency = 120; private static readonly TimeSpan _defaultReportingIntervals = TimeSpan.FromSeconds(5); - public SyncReport(ISyncPeerPool syncPeerPool, INodeStatsManager nodeStatsManager, ISyncConfig syncConfig, IPivot pivot, ILogManager logManager, ITimerFactory? timerFactory = null, double tickTime = 1000) { _logger = logManager?.GetClassLogger() ?? throw new ArgumentNullException(nameof(logManager)); @@ -121,20 +121,7 @@ private void TimerOnElapsed(object? sender, EventArgs e) public long FullSyncBlocksKnown { get; set; } - private static string Pad(decimal value, int length) - { - string valueString = $"{value:N0}"; - return valueString.PadLeft(length + 3, ' '); - } - - private static string Pad(long value, int length) - { - string valueString = $"{value:N0}"; - return valueString.PadLeft(length, ' '); - } - private bool _reportedFastBlocksSummary; - private int _blockPaddingLength; private string _paddedPivot; private string _paddedAmountOfOldBodiesToDownload; private string _paddedAmountOfOldReceiptsToDownload; @@ -145,14 +132,13 @@ private static string Pad(long value, int length) private void SetPaddedPivots() { _fastBlocksPivotNumber = _syncConfig.PivotNumberParsed; - _blockPaddingLength = _fastBlocksPivotNumber.ToString("N0").Length; - _paddedPivot = $"{Pad(_fastBlocksPivotNumber, _blockPaddingLength)}"; + _paddedPivot = $"{_fastBlocksPivotNumber,BlockPaddingLength:N0}"; long amountOfBodiesToDownload = _fastBlocksPivotNumber - _syncConfig.AncientBodiesBarrier; _amountOfBodiesToDownload = amountOfBodiesToDownload; - _paddedAmountOfOldBodiesToDownload = $"{Pad(amountOfBodiesToDownload, $"{amountOfBodiesToDownload}".Length)}"; + _paddedAmountOfOldBodiesToDownload = $"{amountOfBodiesToDownload,BlockPaddingLength:N0}"; long amountOfReceiptsToDownload = _fastBlocksPivotNumber - _syncConfig.AncientReceiptsBarrier; _amountOfReceiptsToDownload = amountOfReceiptsToDownload; - _paddedAmountOfOldReceiptsToDownload = $"{Pad(_fastBlocksPivotNumber - _syncConfig.AncientReceiptsBarrier, $"{amountOfReceiptsToDownload}".Length)}"; + _paddedAmountOfOldReceiptsToDownload = $"{_fastBlocksPivotNumber - _syncConfig.AncientReceiptsBarrier,BlockPaddingLength:N0}"; } private void WriteSyncReport() @@ -297,7 +283,7 @@ private void WriteFullSyncReport() } float percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); - string downloadReport = $"Downloaded {Pad(FullSyncBlocksDownloaded.CurrentValue, _blockPaddingLength)} / {Pad(FullSyncBlocksKnown, _blockPaddingLength)} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} | current {Pad(FullSyncBlocksDownloaded.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; + string downloadReport = $"Downloaded {FullSyncBlocksDownloaded.CurrentValue,BlockPaddingLength:N0} / {FullSyncBlocksKnown,BlockPaddingLength:N0} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} | current {FullSyncBlocksDownloaded.CurrentPerSecond,SpeedPaddingLength:N0} Blk/s"; // Compare ignoring speed change if (!_lastDownloadReport.AsSpan().StartsWith(downloadReport.AsSpan(0, downloadReport.LastIndexOf("| current")))) { @@ -312,7 +298,7 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) if ((currentSyncMode & SyncMode.FastHeaders) == SyncMode.FastHeaders) { float percentage = Math.Clamp(FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1), 0, 1); - string headersReport = $"Old Headers {Pad(FastBlocksHeaders.CurrentValue, _blockPaddingLength)} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(HeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; + string headersReport = $"Old Headers {FastBlocksHeaders.CurrentValue,BlockPaddingLength:N0} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {HeadersInQueue.CurrentValue,QueuePaddingLength:N0} | current {FastBlocksHeaders.CurrentPerSecond,SpeedPaddingLength:N0} Blk/s"; // Compare ignoring speed change if (!_lastHeadersReport.AsSpan().StartsWith(headersReport.AsSpan(0, headersReport.LastIndexOf("| current")))) { @@ -325,7 +311,7 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) if ((currentSyncMode & SyncMode.FastBodies) == SyncMode.FastBodies) { float percentage = Math.Clamp(FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1), 0, 1); - string bodiesReport = $"Old Bodies {Pad(FastBlocksBodies.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(BodiesInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksBodies.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; + string bodiesReport = $"Old Bodies {FastBlocksBodies.CurrentValue,BlockPaddingLength:N0} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {BodiesInQueue.CurrentValue,QueuePaddingLength:N0} | current {FastBlocksBodies.CurrentPerSecond,SpeedPaddingLength:N0} Blk/s"; // Compare ignoring speed change if (!_lastBodiesReport.AsSpan().StartsWith(bodiesReport.AsSpan(0, bodiesReport.LastIndexOf("| current")))) { @@ -338,7 +324,7 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) if ((currentSyncMode & SyncMode.FastReceipts) == SyncMode.FastReceipts) { float percentage = Math.Clamp(FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1), 0, 1); - string receiptsReport = $"Old Receipts {Pad(FastBlocksReceipts.CurrentValue, _blockPaddingLength)} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {Pad(ReceiptsInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(FastBlocksReceipts.CurrentPerSecond, SpeedPaddingLength)} Blk/s"; + string receiptsReport = $"Old Receipts {FastBlocksReceipts.CurrentValue,BlockPaddingLength:N0} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {ReceiptsInQueue.CurrentValue,QueuePaddingLength:N0} | current {FastBlocksReceipts.CurrentPerSecond,SpeedPaddingLength:N0} Blk/s"; // Compare ignoring speed change if (!_lastReceiptsReport.AsSpan().StartsWith(receiptsReport.AsSpan(0, receiptsReport.LastIndexOf("| current")))) { @@ -352,9 +338,8 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) private void WriteBeaconSyncReport() { long numHeadersToDownload = _pivot.PivotNumber - _pivot.PivotDestinationNumber + 1; - int paddingLength = numHeadersToDownload.ToString("N0").Length; _logger.Info($"Beacon Headers from block {_pivot.PivotDestinationNumber} to block {_pivot.PivotNumber} | " - + $"{Pad(BeaconHeaders.CurrentValue, paddingLength)} / {Pad(numHeadersToDownload, paddingLength)} | queue {Pad(BeaconHeadersInQueue.CurrentValue, QueuePaddingLength)} | current {Pad(BeaconHeaders.CurrentPerSecond, SpeedPaddingLength)} Blk/s | total {Pad(BeaconHeaders.TotalPerSecond, SpeedPaddingLength)} Blk/s"); + + $"{BeaconHeaders.CurrentValue,BlockPaddingLength:N0} / {numHeadersToDownload,BlockPaddingLength:N0} | queue {BeaconHeadersInQueue.CurrentValue,QueuePaddingLength:N0} | current {BeaconHeaders.CurrentPerSecond,SpeedPaddingLength:N0} Blk/s | total {BeaconHeaders.TotalPerSecond,SpeedPaddingLength:N0} Blk/s"); BeaconHeaders.SetMeasuringPoint(); } From fd4bdfc2349a42b9dec7e0141727af0bcb260eb3 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 15:16:22 +0100 Subject: [PATCH 18/21] Less multi line spam --- .../Nethermind.Synchronization/FastSync/DetailedProgress.cs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs index 393fa29c78d..d4301242f9b 100644 --- a/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs +++ b/src/Nethermind/Nethermind.Synchronization/FastSync/DetailedProgress.cs @@ -82,7 +82,9 @@ internal void DisplayProgressReport(int pendingRequestsCount, BranchProgress bra if (logger.IsInfo) { - string stateSyncReport = $"State Sync {dataSizeInfo} branches: {branchProgress.Progress:P2} | kB/s: {savedKBytesPerSecond,5:F0} | accounts {SavedAccounts} | nodes {SavedNodesCount} | pending: {pendingRequestsCount,3}"; + 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; From 6cee0e5dce9d9551921bd4b0c8dac5ad158fcbd7 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Sat, 22 Jun 2024 17:53:56 +0100 Subject: [PATCH 19/21] DarkGrey progress bar --- src/Nethermind/Nethermind.Runner/NLog.config | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/Nethermind/Nethermind.Runner/NLog.config b/src/Nethermind/Nethermind.Runner/NLog.config index 92088881c18..d99f39d9003 100644 --- a/src/Nethermind/Nethermind.Runner/NLog.config +++ b/src/Nethermind/Nethermind.Runner/NLog.config @@ -77,6 +77,8 @@ + + From 7891d6eba7718987133aa1c902672db47cc4a411 Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Wed, 26 Jun 2024 18:22:20 +0100 Subject: [PATCH 20/21] Feedback --- src/Nethermind/Nethermind.Logging/Progress.cs | 27 +++++++++++---- .../Reporting/SyncReport.cs | 34 ++++++++++--------- 2 files changed, 39 insertions(+), 22 deletions(-) diff --git a/src/Nethermind/Nethermind.Logging/Progress.cs b/src/Nethermind/Nethermind.Logging/Progress.cs index 7754685a4c2..523d9e7a97f 100644 --- a/src/Nethermind/Nethermind.Logging/Progress.cs +++ b/src/Nethermind/Nethermind.Logging/Progress.cs @@ -4,17 +4,32 @@ using System; namespace Nethermind.Logging; -public class Progress +public static class Progress { - private static char[] _progressChars = { ' ', '⡀', '⡄', '⡆', '⡇', '⣇', '⣧', '⣷', '⣿' }; + private const int Width = 40; + private const int WidthBar = Width - 3; - public static string GetMeter(float value, int max, int width = 40) + 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) { - width = Math.Max(4, width - 3); - float progressF = value / max * width; + float progressF = value / max * WidthBar; int progress = (int)Math.Floor(progressF); int progressChar = (int)((progressF - progress) * _progressChars.Length); - return $"[{new string('⣿', progress)}{_progressChars[progressChar]}{new string(' ', width - progress - 1)}]"; + return string.Concat(_fullChunks[progress], _progressChars[progressChar], _emptyChunks[WidthBar - progress - 1]); } } diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index eb637c6d9ea..fc11444500c 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -282,10 +282,8 @@ private void WriteFullSyncReport() return; } - float percentage = Math.Clamp(FullSyncBlocksDownloaded.CurrentValue / (float)(FullSyncBlocksKnown + 1), 0, 1); - string downloadReport = $"Downloaded {FullSyncBlocksDownloaded.CurrentValue,BlockPaddingLength:N0} / {FullSyncBlocksKnown,BlockPaddingLength:N0} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} | current {FullSyncBlocksDownloaded.CurrentPerSecond,SpeedPaddingLength:N0} Blk/s"; - // Compare ignoring speed change - if (!_lastDownloadReport.AsSpan().StartsWith(downloadReport.AsSpan(0, downloadReport.LastIndexOf("| current")))) + string downloadReport = GenerateReport("Downloaded ", FullSyncBlocksDownloaded.CurrentValue, FullSyncBlocksKnown, queue: -1, FullSyncBlocksDownloaded.CurrentPerSecond); + if (!EqualsIgnoringSpeed(_lastDownloadReport, downloadReport)) { _lastDownloadReport = downloadReport; _logger.Info(downloadReport); @@ -297,10 +295,8 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) { if ((currentSyncMode & SyncMode.FastHeaders) == SyncMode.FastHeaders) { - float percentage = Math.Clamp(FastBlocksHeaders.CurrentValue / (float)(_fastBlocksPivotNumber + 1), 0, 1); - string headersReport = $"Old Headers {FastBlocksHeaders.CurrentValue,BlockPaddingLength:N0} / {_paddedPivot} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {HeadersInQueue.CurrentValue,QueuePaddingLength:N0} | current {FastBlocksHeaders.CurrentPerSecond,SpeedPaddingLength:N0} Blk/s"; - // Compare ignoring speed change - if (!_lastHeadersReport.AsSpan().StartsWith(headersReport.AsSpan(0, headersReport.LastIndexOf("| current")))) + string headersReport = GenerateReport("Old Headers ", FastBlocksHeaders.CurrentValue, _fastBlocksPivotNumber, HeadersInQueue.CurrentValue, FastBlocksHeaders.CurrentPerSecond); + if (!EqualsIgnoringSpeed(_lastHeadersReport, headersReport)) { _lastHeadersReport = headersReport; _logger.Info(headersReport); @@ -310,10 +306,8 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) if ((currentSyncMode & SyncMode.FastBodies) == SyncMode.FastBodies) { - float percentage = Math.Clamp(FastBlocksBodies.CurrentValue / (float)(_amountOfBodiesToDownload + 1), 0, 1); - string bodiesReport = $"Old Bodies {FastBlocksBodies.CurrentValue,BlockPaddingLength:N0} / {_paddedAmountOfOldBodiesToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {BodiesInQueue.CurrentValue,QueuePaddingLength:N0} | current {FastBlocksBodies.CurrentPerSecond,SpeedPaddingLength:N0} Blk/s"; - // Compare ignoring speed change - if (!_lastBodiesReport.AsSpan().StartsWith(bodiesReport.AsSpan(0, bodiesReport.LastIndexOf("| current")))) + string bodiesReport = GenerateReport("Old Bodies ", FastBlocksBodies.CurrentValue, _amountOfBodiesToDownload, BodiesInQueue.CurrentValue, FastBlocksBodies.CurrentPerSecond); + if (!EqualsIgnoringSpeed(_lastBodiesReport, bodiesReport)) { _lastBodiesReport = bodiesReport; _logger.Info(bodiesReport); @@ -323,10 +317,8 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) if ((currentSyncMode & SyncMode.FastReceipts) == SyncMode.FastReceipts) { - float percentage = Math.Clamp(FastBlocksReceipts.CurrentValue / (float)(_amountOfReceiptsToDownload + 1), 0, 1); - string receiptsReport = $"Old Receipts {FastBlocksReceipts.CurrentValue,BlockPaddingLength:N0} / {_paddedAmountOfOldReceiptsToDownload} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)} queue {ReceiptsInQueue.CurrentValue,QueuePaddingLength:N0} | current {FastBlocksReceipts.CurrentPerSecond,SpeedPaddingLength:N0} Blk/s"; - // Compare ignoring speed change - if (!_lastReceiptsReport.AsSpan().StartsWith(receiptsReport.AsSpan(0, receiptsReport.LastIndexOf("| current")))) + string receiptsReport = GenerateReport("Old Receipts", FastBlocksReceipts.CurrentValue, _amountOfReceiptsToDownload, ReceiptsInQueue.CurrentValue, FastBlocksReceipts.CurrentPerSecond); + if (!EqualsIgnoringSpeed(_lastReceiptsReport, receiptsReport)) { _lastReceiptsReport = receiptsReport; _logger.Info(receiptsReport); @@ -335,6 +327,16 @@ private void WriteFastBlocksReport(SyncMode currentSyncMode) } } + private static string GenerateReport(string title, long current, long total, long queue, decimal speed) + { + float percentage = Math.Clamp(current / (float)(total + 1), 0, 1); + string receiptsReport = $"{title} {current,BlockPaddingLength:N0} / {total,BlockPaddingLength:N0} ({percentage,8:P2}) {Progress.GetMeter(percentage, 1)}{(queue >= 0 ? $" queue {queue,QueuePaddingLength:N0} " : " ")}| current {speed,SpeedPaddingLength:N0} Blk/s"; + return receiptsReport; + } + + private static bool EqualsIgnoringSpeed(string? lastReport, string report) + => lastReport.AsSpan().StartsWith(report.AsSpan(0, report.LastIndexOf("| current"))); + private void WriteBeaconSyncReport() { long numHeadersToDownload = _pivot.PivotNumber - _pivot.PivotDestinationNumber + 1; From 12040bf56fcc86f0ff58d69f37981bebaa38191b Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Wed, 26 Jun 2024 18:25:38 +0100 Subject: [PATCH 21/21] Remove unused fields --- .../Reporting/SyncReport.cs | 12 ++---------- 1 file changed, 2 insertions(+), 10 deletions(-) diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index fc11444500c..f52c739ab54 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -122,9 +122,6 @@ private void TimerOnElapsed(object? sender, EventArgs e) public long FullSyncBlocksKnown { get; set; } private bool _reportedFastBlocksSummary; - private string _paddedPivot; - private string _paddedAmountOfOldBodiesToDownload; - private string _paddedAmountOfOldReceiptsToDownload; private long _amountOfBodiesToDownload; private long _amountOfReceiptsToDownload; private uint _nodeInfoType; @@ -132,13 +129,8 @@ private void TimerOnElapsed(object? sender, EventArgs e) private void SetPaddedPivots() { _fastBlocksPivotNumber = _syncConfig.PivotNumberParsed; - _paddedPivot = $"{_fastBlocksPivotNumber,BlockPaddingLength:N0}"; - long amountOfBodiesToDownload = _fastBlocksPivotNumber - _syncConfig.AncientBodiesBarrier; - _amountOfBodiesToDownload = amountOfBodiesToDownload; - _paddedAmountOfOldBodiesToDownload = $"{amountOfBodiesToDownload,BlockPaddingLength:N0}"; - long amountOfReceiptsToDownload = _fastBlocksPivotNumber - _syncConfig.AncientReceiptsBarrier; - _amountOfReceiptsToDownload = amountOfReceiptsToDownload; - _paddedAmountOfOldReceiptsToDownload = $"{_fastBlocksPivotNumber - _syncConfig.AncientReceiptsBarrier,BlockPaddingLength:N0}"; + _amountOfBodiesToDownload = _fastBlocksPivotNumber - _syncConfig.AncientBodiesBarrier; + _amountOfReceiptsToDownload = _fastBlocksPivotNumber - _syncConfig.AncientReceiptsBarrier; } private void WriteSyncReport()