From ce26652ec726354e7f764f495963346131510e3f Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Mon, 12 Jun 2023 19:29:10 +0100 Subject: [PATCH] Move detailed peer logging to debug, add diversity (#5795) * Move detailed peer logging to debug, add diversity * Formatting * Use enum * Add context summary counts * Output correct * Fix * Tweaks * Change to struct * Undo report change * Retry flaky test --- .../Nethermind.Network.Stats/Model/Node.cs | 18 ++- .../Model/NodeClientType.cs | 5 +- .../ParallelSync/SyncDispatcherTests.cs | 1 + .../Blocks/BlockDownloaderLimits.cs | 6 +- .../Peers/SyncPeersReport.cs | 131 +++++++++++++++++- .../Reporting/SyncReport.cs | 2 +- 6 files changed, 143 insertions(+), 20 deletions(-) diff --git a/src/Nethermind/Nethermind.Network.Stats/Model/Node.cs b/src/Nethermind/Nethermind.Network.Stats/Model/Node.cs index 001dbdbce5f..ebca63b426d 100644 --- a/src/Nethermind/Nethermind.Network.Stats/Model/Node.cs +++ b/src/Nethermind/Nethermind.Network.Stats/Model/Node.cs @@ -170,27 +170,31 @@ public static NodeClientType RecognizeClientType(string clientId) { return NodeClientType.Unknown; } - else if (clientId.Contains("BeSu", StringComparison.InvariantCultureIgnoreCase)) + else if (clientId.Contains(nameof(NodeClientType.Besu), StringComparison.OrdinalIgnoreCase)) { - return NodeClientType.BeSu; + return NodeClientType.Besu; } - else if (clientId.Contains("Geth", StringComparison.InvariantCultureIgnoreCase)) + else if (clientId.Contains(nameof(NodeClientType.Geth), StringComparison.OrdinalIgnoreCase)) { return NodeClientType.Geth; } - else if (clientId.Contains("Nethermind", StringComparison.InvariantCultureIgnoreCase)) + else if (clientId.Contains(nameof(NodeClientType.Nethermind), StringComparison.OrdinalIgnoreCase)) { return NodeClientType.Nethermind; } - else if (clientId.Contains("Parity", StringComparison.InvariantCultureIgnoreCase)) + else if (clientId.Contains(nameof(NodeClientType.Erigon), StringComparison.OrdinalIgnoreCase)) + { + return NodeClientType.Erigon; + } + else if (clientId.Contains(nameof(NodeClientType.Parity), StringComparison.OrdinalIgnoreCase)) { return NodeClientType.Parity; } - else if (clientId.Contains("OpenEthereum", StringComparison.InvariantCultureIgnoreCase)) + else if (clientId.Contains(nameof(NodeClientType.OpenEthereum), StringComparison.OrdinalIgnoreCase)) { return NodeClientType.OpenEthereum; } - else if (clientId.Contains("Trinity", StringComparison.InvariantCultureIgnoreCase)) + else if (clientId.Contains(nameof(NodeClientType.Trinity), StringComparison.OrdinalIgnoreCase)) { return NodeClientType.Trinity; } diff --git a/src/Nethermind/Nethermind.Network.Stats/Model/NodeClientType.cs b/src/Nethermind/Nethermind.Network.Stats/Model/NodeClientType.cs index ef5ff306e77..be5ec95ac06 100644 --- a/src/Nethermind/Nethermind.Network.Stats/Model/NodeClientType.cs +++ b/src/Nethermind/Nethermind.Network.Stats/Model/NodeClientType.cs @@ -5,12 +5,13 @@ namespace Nethermind.Stats.Model { public enum NodeClientType { - BeSu, + Unknown = 0, + Besu, Geth, Nethermind, Parity, OpenEthereum, Trinity, - Unknown + Erigon, } } diff --git a/src/Nethermind/Nethermind.Synchronization.Test/ParallelSync/SyncDispatcherTests.cs b/src/Nethermind/Nethermind.Synchronization.Test/ParallelSync/SyncDispatcherTests.cs index 0c50884b9f9..30700f5f208 100644 --- a/src/Nethermind/Nethermind.Synchronization.Test/ParallelSync/SyncDispatcherTests.cs +++ b/src/Nethermind/Nethermind.Synchronization.Test/ParallelSync/SyncDispatcherTests.cs @@ -270,6 +270,7 @@ public async Task Simple_test_sync() } } + [Retry(tryCount: 5)] [TestCase(false, 1, 1, 8)] [TestCase(true, 1, 1, 24)] [TestCase(true, 2, 1, 32)] diff --git a/src/Nethermind/Nethermind.Synchronization/Blocks/BlockDownloaderLimits.cs b/src/Nethermind/Nethermind.Synchronization/Blocks/BlockDownloaderLimits.cs index 40ee4b09925..eab7096c8ce 100644 --- a/src/Nethermind/Nethermind.Synchronization/Blocks/BlockDownloaderLimits.cs +++ b/src/Nethermind/Nethermind.Synchronization/Blocks/BlockDownloaderLimits.cs @@ -14,7 +14,7 @@ public static int MaxBodiesPerRequest(this PeerInfo peer) { return peer.PeerClientType switch { - NodeClientType.BeSu => BeSuSyncLimits.MaxBodyFetch, + NodeClientType.Besu => BeSuSyncLimits.MaxBodyFetch, NodeClientType.Geth => GethSyncLimits.MaxBodyFetch, NodeClientType.Nethermind => NethermindSyncLimits.MaxBodyFetch, NodeClientType.Parity => ParitySyncLimits.MaxBodyFetch, @@ -29,7 +29,7 @@ public static int MaxReceiptsPerRequest(this PeerInfo peer) { return peer.PeerClientType switch { - NodeClientType.BeSu => BeSuSyncLimits.MaxReceiptFetch, + NodeClientType.Besu => BeSuSyncLimits.MaxReceiptFetch, NodeClientType.Geth => GethSyncLimits.MaxReceiptFetch, NodeClientType.Nethermind => NethermindSyncLimits.MaxReceiptFetch, NodeClientType.Parity => ParitySyncLimits.MaxReceiptFetch, @@ -43,7 +43,7 @@ public static int MaxHeadersPerRequest(this PeerInfo peer) { return peer.PeerClientType switch { - NodeClientType.BeSu => BeSuSyncLimits.MaxHeaderFetch, + NodeClientType.Besu => BeSuSyncLimits.MaxHeaderFetch, NodeClientType.Geth => GethSyncLimits.MaxHeaderFetch, NodeClientType.Nethermind => NethermindSyncLimits.MaxHeaderFetch, NodeClientType.Parity => ParitySyncLimits.MaxHeaderFetch, diff --git a/src/Nethermind/Nethermind.Synchronization/Peers/SyncPeersReport.cs b/src/Nethermind/Nethermind.Synchronization/Peers/SyncPeersReport.cs index 839947c84c4..ce1d5762ba1 100644 --- a/src/Nethermind/Nethermind.Synchronization/Peers/SyncPeersReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Peers/SyncPeersReport.cs @@ -7,6 +7,7 @@ using System.Text; using Nethermind.Logging; using Nethermind.Stats; +using Nethermind.Stats.Model; namespace Nethermind.Synchronization.Peers { @@ -41,16 +42,17 @@ public SyncPeersReport(ISyncPeerPool peerPool, INodeStatsManager statsManager, I public void WriteFullReport() { - lock (_writeLock) + if (!_logger.IsDebug) { - if (!_logger.IsInfo) - { - return; - } + return; + } + lock (_writeLock) + { RememberState(out bool _); - _logger.Info(MakeReportForPeer(OrderedPeers, $"Sync peers - Initialized: {_currentInitializedPeerCount} | All: {_peerPool.PeerCount} | Max: {_peerPool.PeerMaxCount}")); + _logger.Debug(MakeSummaryReportForPeers(_peerPool.InitializedPeers, $"Sync peers - Connected: {_currentInitializedPeerCount} | All: {_peerPool.PeerCount} | Max: {_peerPool.PeerMaxCount}")); + _logger.Debug(MakeReportForPeer(OrderedPeers, "")); } } @@ -69,7 +71,77 @@ public void WriteAllocatedReport() return; } - _logger.Info(MakeReportForPeer(OrderedPeers.Where(p => (p.AllocatedContexts & AllocationContexts.All) != AllocationContexts.None), $"Allocated sync peers {_currentInitializedPeerCount}({_peerPool.PeerCount})/{_peerPool.PeerMaxCount}")); + var header = $"Allocated sync peers {_currentInitializedPeerCount}({_peerPool.PeerCount})/{_peerPool.PeerMaxCount}"; + if (_logger.IsDebug) + { + _logger.Debug(MakeReportForPeer(OrderedPeers.Where(p => (p.AllocatedContexts & AllocationContexts.All) != AllocationContexts.None), header)); + } + else + { + _logger.Info(MakeSummaryReportForPeers(_peerPool.InitializedPeers, header)); + } + } + } + + internal string? MakeSummaryReportForPeers(IEnumerable peers, string header) + { + lock (_writeLock) + { + IEnumerable> peerGroups = peers.GroupBy(peerInfo => peerInfo.SyncPeer.ClientType); + float sum = peerGroups.Sum(x => x.Count()); + + _stringBuilder.Append(header); + _stringBuilder.Append(" |"); + + PeersContextCounts activeContexts = new(); + PeersContextCounts sleepingContexts = new(); + foreach (PeerInfo peerInfo in peers) + { + CountContexts(peerInfo.AllocatedContexts, ref activeContexts); + CountContexts(peerInfo.SleepingContexts, ref sleepingContexts); + } + + _stringBuilder.Append(" Active: "); + activeContexts.AppendTo(_stringBuilder, "None"); + _stringBuilder.Append(" | Sleeping: "); + sleepingContexts.AppendTo(_stringBuilder, activeContexts.Total != activeContexts.None ? "None" : "All"); + _stringBuilder.Append(" |"); + + bool isFirst = true; + foreach (var peerGroup in peerGroups.OrderByDescending(x => x.Count())) + { + if (isFirst) + { + isFirst = false; + } + else + { + _stringBuilder.Append(','); + } + _stringBuilder.Append($" {peerGroup.Key} ({peerGroup.Count() / sum,6:P2})"); + } + + string result = _stringBuilder.ToString(); + _stringBuilder.Clear(); + return result; + } + + static void CountContexts(AllocationContexts contexts, ref PeersContextCounts contextCounts) + { + contextCounts.Total++; + if (contexts == AllocationContexts.None) + { + contextCounts.None++; + return; + } + + contextCounts.Headers += contexts.HasFlag(AllocationContexts.Headers) ? 1 : 0; + contextCounts.Bodies += contexts.HasFlag(AllocationContexts.Bodies) ? 1 : 0; + contextCounts.Receipts += contexts.HasFlag(AllocationContexts.Receipts) ? 1 : 0; + contextCounts.Blocks += contexts.HasFlag(AllocationContexts.Blocks) ? 1 : 0; + contextCounts.State += contexts.HasFlag(AllocationContexts.State) ? 1 : 0; + contextCounts.Witness += contexts.HasFlag(AllocationContexts.Witness) ? 1 : 0; + contextCounts.Snap += contexts.HasFlag(AllocationContexts.Snap) ? 1 : 0; } } @@ -135,5 +207,50 @@ private void RememberState(out bool initializedCountChanged) initializedCountChanged = initializedPeerCount != _currentInitializedPeerCount; _currentInitializedPeerCount = initializedPeerCount; } + + private struct PeersContextCounts + { + public int None { get; set; } + public int Headers { get; set; } + public int Bodies { get; set; } + public int Receipts { get; set; } + public int Blocks { get; set; } + public int State { get; set; } + public int Witness { get; set; } + public int Snap { get; set; } + public int Total { get; set; } + + public void AppendTo(StringBuilder sb, string allText) + { + if (Total == None) + { + sb.Append(allText); + return; + } + + bool added = false; + + if (Headers > 0) AddComma(sb, ref added).Append(Headers).Append(" Headers"); + if (Bodies > 0) AddComma(sb, ref added).Append(Bodies).Append(" Bodies"); + if (Receipts > 0) AddComma(sb, ref added).Append(Receipts).Append(" Receipts"); + if (Blocks > 0) AddComma(sb, ref added).Append(Blocks).Append(" Blocks"); + if (State > 0) AddComma(sb, ref added).Append(State).Append(" State"); + if (Witness > 0) AddComma(sb, ref added).Append(Witness).Append(" Witness"); + if (Snap > 0) AddComma(sb, ref added).Append(Snap).Append(" Snap"); + + StringBuilder AddComma(StringBuilder sb, ref bool itemAdded) + { + if (itemAdded) + { + sb.Append(", "); + } + else + { + itemAdded = true; + } + return sb; + } + } + } } } diff --git a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs index a05642c3643..b2c0da67f42 100644 --- a/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs +++ b/src/Nethermind/Nethermind.Synchronization/Reporting/SyncReport.cs @@ -174,7 +174,7 @@ private void WriteSyncReport() { if (_reportId % PeerCountFrequency == 0) { - _logger.Info($"Peers | with known best block: {_syncPeerPool.InitializedPeersCount} | all: {_syncPeerPool.PeerCount} |"); + _logger.Info(_syncPeersReport.MakeSummaryReportForPeers(_syncPeerPool.InitializedPeers, $"Peers | with known best block: {_syncPeerPool.InitializedPeersCount} | all: {_syncPeerPool.PeerCount}")); } }