diff --git a/src/Nethermind/Nethermind.Logging/Progress.cs b/src/Nethermind/Nethermind.Logging/Progress.cs new file mode 100644 index 00000000000..523d9e7a97f --- /dev/null +++ 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 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.Runner/NLog.config b/src/Nethermind/Nethermind.Runner/NLog.config index 01f4f050a8f..d99f39d9003 100644 --- a/src/Nethermind/Nethermind.Runner/NLog.config +++ b/src/Nethermind/Nethermind.Runner/NLog.config @@ -49,7 +49,7 @@ - + @@ -77,6 +77,8 @@ + + diff --git a/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs b/src/Nethermind/Nethermind.Synchronization.Test/SyncReportTest.cs index 074cb71ee56..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 | 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 index 7d804204ed6..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++) { @@ -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 index 669ec926fa4..d4301242f9b 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; @@ -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 index c33e126b4f3..e9eff01f553 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) @@ -288,8 +288,9 @@ 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}"; + 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}"; diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index f088c7b1430..f52c739ab54 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -15,7 +15,9 @@ namespace Nethermind.Synchronization.Reporting { public class SyncReport : ISyncReport { - private const int SpeedPaddingLength = 9; + private const int QueuePaddingLength = 8; + private const int SpeedPaddingLength = 7; + private const int BlockPaddingLength = 10; private readonly ISyncPeerPool _syncPeerPool; private readonly ISyncConfig _syncConfig; @@ -32,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)); @@ -64,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}"); } } @@ -94,6 +96,10 @@ 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; public MeasuredProgress HeadersInQueue { get; } = new(); @@ -115,23 +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; private long _amountOfBodiesToDownload; private long _amountOfReceiptsToDownload; private uint _nodeInfoType; @@ -139,14 +129,8 @@ private static string Pad(long value, int length) private void SetPaddedPivots() { _fastBlocksPivotNumber = _syncConfig.PivotNumberParsed; - _blockPaddingLength = _fastBlocksPivotNumber.ToString("N0").Length; - _paddedPivot = $"{Pad(_fastBlocksPivotNumber, _blockPaddingLength)}"; - long amountOfBodiesToDownload = _fastBlocksPivotNumber - _syncConfig.AncientBodiesBarrier; - _amountOfBodiesToDownload = amountOfBodiesToDownload; - _paddedAmountOfOldBodiesToDownload = $"{Pad(amountOfBodiesToDownload, $"{amountOfBodiesToDownload}".Length)}"; - long amountOfReceiptsToDownload = _fastBlocksPivotNumber - _syncConfig.AncientReceiptsBarrier; - _amountOfReceiptsToDownload = amountOfReceiptsToDownload; - _paddedAmountOfOldReceiptsToDownload = $"{Pad(_fastBlocksPivotNumber - _syncConfig.AncientReceiptsBarrier, $"{amountOfReceiptsToDownload}".Length)}"; + _amountOfBodiesToDownload = _fastBlocksPivotNumber - _syncConfig.AncientBodiesBarrier; + _amountOfReceiptsToDownload = _fastBlocksPivotNumber - _syncConfig.AncientReceiptsBarrier; } private void WriteSyncReport() @@ -290,7 +274,12 @@ 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"); + string downloadReport = GenerateReport("Downloaded ", FullSyncBlocksDownloaded.CurrentValue, FullSyncBlocksKnown, queue: -1, FullSyncBlocksDownloaded.CurrentPerSecond); + if (!EqualsIgnoringSpeed(_lastDownloadReport, downloadReport)) + { + _lastDownloadReport = downloadReport; + _logger.Info(downloadReport); + } FullSyncBlocksDownloaded.SetMeasuringPoint(); } @@ -298,29 +287,53 @@ 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"); + string headersReport = GenerateReport("Old Headers ", FastBlocksHeaders.CurrentValue, _fastBlocksPivotNumber, HeadersInQueue.CurrentValue, FastBlocksHeaders.CurrentPerSecond); + if (!EqualsIgnoringSpeed(_lastHeadersReport, headersReport)) + { + _lastHeadersReport = headersReport; + _logger.Info(headersReport); + } 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"); + string bodiesReport = GenerateReport("Old Bodies ", FastBlocksBodies.CurrentValue, _amountOfBodiesToDownload, BodiesInQueue.CurrentValue, FastBlocksBodies.CurrentPerSecond); + if (!EqualsIgnoringSpeed(_lastBodiesReport, bodiesReport)) + { + _lastBodiesReport = bodiesReport; + _logger.Info(bodiesReport); + } 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"); + string receiptsReport = GenerateReport("Old Receipts", FastBlocksReceipts.CurrentValue, _amountOfReceiptsToDownload, ReceiptsInQueue.CurrentValue, FastBlocksReceipts.CurrentPerSecond); + if (!EqualsIgnoringSpeed(_lastReceiptsReport, receiptsReport)) + { + _lastReceiptsReport = receiptsReport; + _logger.Info(receiptsReport); + } FastBlocksReceipts.SetMeasuringPoint(); } } + 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; - 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"); + + $"{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(); } diff --git a/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs b/src/Nethermind/Nethermind.Synchronization/SnapSync/ProgressTracker.cs index 4e0f9722f80..eda6709e66e 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,14 +422,22 @@ 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) + { + 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) + 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}"); } }