From e5e41329faa9ce8aa676d3d85d20988a42379c27 Mon Sep 17 00:00:00 2001 From: Shubham Sonthalia Date: Sat, 5 Oct 2024 17:36:36 +0530 Subject: [PATCH 1/3] Updating stopwatch.startNew logic to startTime in all methods. --- src/Nethermind/Nethermind.Cli/NodeManager.cs | 12 ++++------ .../CliqueBlockProducerTests.cs | 5 ++-- .../Nethermind.Evm.Test/Eip1153Tests.cs | 6 ++--- .../Proxy/DefaultHttpClient.cs | 6 ++--- .../Steps/EthereumStepsManager.cs | 9 ++++--- .../Steps/InitializePlugins.cs | 5 ++-- .../Nethermind.JsonRpc/JsonRpcProcessor.cs | 24 +++++++------------ .../WebSockets/JsonRpcSocketsClient.cs | 10 ++++---- .../EngineRpcModule.Paris.cs | 10 ++++---- .../Synchronization/MergeBlockDownloader.cs | 4 ++-- .../DiscoveryManagerTests.cs | 4 ++-- .../EnrDiscoveryTests.cs | 4 ++-- .../ProtocolHandlers/P2PProtocolHandler.cs | 4 ++-- .../SyncPeerProtocolHandlerBase.cs | 15 +++++------- .../Eth/V63/Eth63ProtocolHandler.cs | 5 ++-- .../Eth/V65/Eth65ProtocolHandler.cs | 10 ++++---- .../Eth/V66/Eth66ProtocolHandler.cs | 5 ++-- .../Nethermind.Runner/JsonRpc/Startup.cs | 4 ++-- src/Nethermind/Nethermind.Runner/Program.cs | 5 ++-- .../Blocks/BlockDownloader.cs | 4 ++-- .../FastSync/PendingSyncItems.cs | 5 ++-- .../FastSync/TreeSync.cs | 13 +++++----- .../PersistentBlobTxDistinctSortedPool.cs | 5 ++-- 23 files changed, 72 insertions(+), 102 deletions(-) diff --git a/src/Nethermind/Nethermind.Cli/NodeManager.cs b/src/Nethermind/Nethermind.Cli/NodeManager.cs index c392a499e59..75cfe3df20f 100644 --- a/src/Nethermind/Nethermind.Cli/NodeManager.cs +++ b/src/Nethermind/Nethermind.Cli/NodeManager.cs @@ -69,11 +69,9 @@ public async Task PostJint(string method, params object[] parameters) } else { - Stopwatch stopwatch = new(); - stopwatch.Start(); + long startTime = Stopwatch.GetTimestamp(); object? result = await _currentClient.Post(method, parameters); - stopwatch.Stop(); - decimal totalMicroseconds = stopwatch.ElapsedTicks * (1_000_000m / Stopwatch.Frequency); + decimal totalMicroseconds = (decimal)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds; Colorful.Console.WriteLine($"Request complete in {totalMicroseconds}μs"); if (result is bool boolResult) @@ -121,11 +119,9 @@ public async Task PostJint(string method, params object[] parameters) } else { - Stopwatch stopwatch = new(); - stopwatch.Start(); + long starting = Stopwatch.GetTimestamp(); result = await _currentClient.Post(method, parameters); - stopwatch.Stop(); - decimal totalMicroseconds = stopwatch.ElapsedTicks * (1_000_000m / Stopwatch.Frequency); + decimal totalMicroseconds = (decimal)Stopwatch.GetElapsedTime(starting).TotalMicroseconds; Colorful.Console.WriteLine($"Request complete in {totalMicroseconds}μs"); } } diff --git a/src/Nethermind/Nethermind.Clique.Test/CliqueBlockProducerTests.cs b/src/Nethermind/Nethermind.Clique.Test/CliqueBlockProducerTests.cs index 2769e365735..b092b6487c2 100644 --- a/src/Nethermind/Nethermind.Clique.Test/CliqueBlockProducerTests.cs +++ b/src/Nethermind/Nethermind.Clique.Test/CliqueBlockProducerTests.cs @@ -424,9 +424,8 @@ private void WaitForNumber(PrivateKey nodeKey, long number) { if (_logger.IsInfo) _logger.Info($"WAITING ON {nodeKey.Address} FOR BLOCK {number}"); SpinWait spinWait = new(); - Stopwatch stopwatch = new(); - stopwatch.Start(); - while (stopwatch.ElapsedMilliseconds < _timeout) + long startTime = Stopwatch.GetTimestamp(); + while (Stopwatch.GetElapsedTime(startTime).TotalMilliseconds < _timeout) { spinWait.SpinOnce(); if (_blockTrees[nodeKey].Head.Number >= number) diff --git a/src/Nethermind/Nethermind.Evm.Test/Eip1153Tests.cs b/src/Nethermind/Nethermind.Evm.Test/Eip1153Tests.cs index 97d509a3b57..0f2e4bed9ff 100644 --- a/src/Nethermind/Nethermind.Evm.Test/Eip1153Tests.cs +++ b/src/Nethermind/Nethermind.Evm.Test/Eip1153Tests.cs @@ -80,7 +80,6 @@ public void tload_uninitialized_returns_zero() [Test] public void transient_storage_performance_test() { - Stopwatch stopwatch = new Stopwatch(); long blockGasLimit = 30000000; long numOfOps = (long)(blockGasLimit * .95) / (GasCostOf.TLoad + GasCostOf.TStore + GasCostOf.VeryLow * 4); Prepare prepare = Prepare.EvmCode; @@ -93,11 +92,10 @@ public void transient_storage_performance_test() byte[] code = prepare.Done; - stopwatch.Start(); + long startTime = Stopwatch.GetTimestamp(); TestAllTracerWithOutput result = Execute((MainnetSpecProvider.GrayGlacierBlockNumber, Timestamp), blockGasLimit, code, blockGasLimit); Assert.That(result.StatusCode, Is.EqualTo(StatusCode.Success)); - stopwatch.Stop(); - Assert.That(stopwatch.ElapsedMilliseconds < 5000, Is.True); + Assert.That(Stopwatch.GetElapsedTime(startTime).TotalMilliseconds < 5000, Is.True); } /// diff --git a/src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs b/src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs index aac11f47041..c4c2db39e12 100644 --- a/src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs +++ b/src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs @@ -79,7 +79,7 @@ private async Task ProcessRequestAsync(Method method, string endpoint, str string methodType = method.ToString(); string json = payload is null ? "{}" : _jsonSerializer.Serialize(payload); if (_logger.IsTrace) _logger.Trace($"Sending HTTP {methodType} request to: {endpoint} [id: {requestId}]{(method == Method.Get ? "." : $": {json}")}"); - Stopwatch stopWatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); HttpResponseMessage response; switch (method) { @@ -94,9 +94,7 @@ private async Task ProcessRequestAsync(Method method, string endpoint, str if (_logger.IsError) _logger.Error($"Unsupported HTTP method: {methodType}."); return default; } - - stopWatch.Stop(); - if (_logger.IsTrace) _logger.Trace($"Received HTTP {methodType} response from: {endpoint} [id: {requestId}, elapsed: {stopWatch.ElapsedMilliseconds} ms]: {response}"); + if (_logger.IsTrace) _logger.Trace($"Received HTTP {methodType} response from: {endpoint} [id: {requestId}, elapsed: {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds} ms]: {response}"); if (!response.IsSuccessStatusCode) { return default; diff --git a/src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs b/src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs index 4912b4ba817..1535e6fbe4d 100644 --- a/src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs +++ b/src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs @@ -147,14 +147,14 @@ private void RunOneRoundOfInitialization(CancellationToken cancellationToken) private async Task ExecuteStep(IStep step, StepInfo stepInfo, CancellationToken cancellationToken) { - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); try { await step.Execute(cancellationToken); if (_logger.IsDebug) _logger.Debug( - $"Step {step.GetType().Name.PadRight(24)} executed in {stopwatch.ElapsedMilliseconds}ms"); + $"Step {step.GetType().Name.PadRight(24)} executed in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); stepInfo.Stage = StepInitializationStage.Complete; } @@ -164,7 +164,7 @@ private async Task ExecuteStep(IStep step, StepInfo stepInfo, CancellationToken { if (_logger.IsError) _logger.Error( - $"Step {step.GetType().Name.PadRight(24)} failed after {stopwatch.ElapsedMilliseconds}ms", + $"Step {step.GetType().Name.PadRight(24)} failed after {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms", exception); stepInfo.Stage = StepInitializationStage.Failed; @@ -174,13 +174,12 @@ private async Task ExecuteStep(IStep step, StepInfo stepInfo, CancellationToken if (_logger.IsWarn) { _logger.Warn( - $"Step {step.GetType().Name.PadRight(24)} failed after {stopwatch.ElapsedMilliseconds}ms {exception}"); + $"Step {step.GetType().Name.PadRight(24)} failed after {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms {exception}"); } stepInfo.Stage = StepInitializationStage.Complete; } finally { - stopwatch.Stop(); _autoResetEvent.Set(); if (_logger.IsDebug) _logger.Debug($"{step.GetType().Name.PadRight(24)} complete"); diff --git a/src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs b/src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs index 31143a8f43e..e1126725b2e 100644 --- a/src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs +++ b/src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs @@ -30,11 +30,10 @@ public async Task Execute(CancellationToken cancellationToken) try { if (logger.IsInfo) logger.Info($" {plugin.Name} by {plugin.Author}"); - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); await plugin.Init(_api); - stopwatch.Stop(); if (logger.IsInfo) - logger.Info($" {plugin.Name} by {plugin.Author} initialized in {stopwatch.ElapsedMilliseconds}ms"); + logger.Info($" {plugin.Name} by {plugin.Author} initialized in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } catch (Exception e) { diff --git a/src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs b/src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs index bcc2a257cab..2c2d448e635 100644 --- a/src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs +++ b/src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs @@ -119,7 +119,7 @@ private ArrayPoolList DeserializeArray(JsonElement element) => public async IAsyncEnumerable ProcessAsync(PipeReader reader, JsonRpcContext context) { reader = await RecordRequest(reader); - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); CancellationTokenSource timeoutSource = new(_jsonRpcConfig.Timeout); // Handles general exceptions during parsing and validation. @@ -130,8 +130,7 @@ JsonRpcResult GetParsingError(string error, Exception? exception = null) if (_logger.IsError) _logger.Error(error, exception); JsonRpcErrorResponse response = _jsonRpcService.GetErrorResponse(ErrorCodes.ParseError, "Incorrect message"); TraceResult(response); - stopwatch.Stop(); - return JsonRpcResult.Single(RecordResponse(response, new RpcReport("# parsing error #", stopwatch.ElapsedMicroseconds(), false))); + return JsonRpcResult.Single(RecordResponse(response, new RpcReport("# parsing error #", (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds, false))); } // Initializes a buffer to store the data read from the reader. @@ -219,9 +218,6 @@ JsonRpcResult GetParsingError(string error, Exception? exception = null) yield return deserializationFailureResult.Value; break; } - - // Stops the stopwatch and yields the batch processing result. - stopwatch.Stop(); JsonRpcBatchResult jsonRpcBatchResult = new((e, c) => IterateRequest(collection, context, e).GetAsyncEnumerator(c)); jsonRpcBatchResult.AddDisposable(() => collection.Dispose()); yield return JsonRpcResult.Collection(jsonRpcBatchResult); @@ -235,9 +231,8 @@ JsonRpcResult GetParsingError(string error, Exception? exception = null) errorResponse.AddDisposable(() => jsonDocument.Dispose()); TraceResult(errorResponse); - stopwatch.Stop(); - if (_logger.IsDebug) _logger.Debug($" Failed request handled in {stopwatch.Elapsed.TotalMilliseconds}ms"); - deserializationFailureResult = JsonRpcResult.Single(RecordResponse(errorResponse, new RpcReport("# parsing error #", stopwatch.ElapsedMicroseconds(), false))); + if (_logger.IsDebug) _logger.Debug($" Failed request handled in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + deserializationFailureResult = JsonRpcResult.Single(RecordResponse(errorResponse, new RpcReport("# parsing error #",(long) Stopwatch.GetElapsedTime(startTime).TotalMilliseconds, false))); yield return deserializationFailureResult.Value; break; } @@ -304,7 +299,7 @@ static bool HasNonWhitespace(ReadOnlySpan span) { try { - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); int requestIndex = 0; for (int index = 0; index < requests.Count; index++) { @@ -325,7 +320,7 @@ static bool HasNonWhitespace(ReadOnlySpan span) yield return RecordResponse(response); } - if (_logger.IsDebug) _logger.Debug($" {requests.Count} requests handled in {stopwatch.Elapsed.TotalMilliseconds}ms"); + if (_logger.IsDebug) _logger.Debug($" {requests.Count} requests handled in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } finally { @@ -336,7 +331,7 @@ static bool HasNonWhitespace(ReadOnlySpan span) private async Task HandleSingleRequest(JsonRpcRequest request, JsonRpcContext context) { Metrics.JsonRpcRequests++; - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); JsonRpcResponse response = await _jsonRpcService.SendRequestAsync(request, context); JsonRpcErrorResponse localErrorResponse = response as JsonRpcErrorResponse; @@ -355,11 +350,10 @@ static bool HasNonWhitespace(ReadOnlySpan span) Metrics.JsonRpcSuccesses++; } - stopwatch.Stop(); - if (_logger.IsDebug) _logger.Debug($" {request} handled in {stopwatch.Elapsed.TotalMilliseconds}ms"); + if (_logger.IsDebug) _logger.Debug($" {request} handled in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); - JsonRpcResult.Entry result = new(response, new RpcReport(request.Method, stopwatch.ElapsedMicroseconds(), isSuccess)); + JsonRpcResult.Entry result = new(response, new RpcReport(request.Method, (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds, isSuccess)); TraceResult(result); return result; } diff --git a/src/Nethermind/Nethermind.JsonRpc/WebSockets/JsonRpcSocketsClient.cs b/src/Nethermind/Nethermind.JsonRpc/WebSockets/JsonRpcSocketsClient.cs index 3cf54185a5e..2c306083d39 100644 --- a/src/Nethermind/Nethermind.JsonRpc/WebSockets/JsonRpcSocketsClient.cs +++ b/src/Nethermind/Nethermind.JsonRpc/WebSockets/JsonRpcSocketsClient.cs @@ -58,7 +58,7 @@ public override void Dispose() public override async Task ProcessAsync(ArraySegment data) { - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); IncrementBytesReceivedMetric(data.Count); PipeReader request = PipeReader.Create(new ReadOnlySequence(data.Array!, data.Offset, data.Count)); int allResponsesSize = 0; @@ -67,23 +67,23 @@ public override async Task ProcessAsync(ArraySegment data) { using (result) { - stopwatch.Restart(); + startTime = Stopwatch.GetTimestamp(); int singleResponseSize = await SendJsonRpcResult(result); allResponsesSize += singleResponseSize; if (result.IsCollection) { - long handlingTimeMicroseconds = stopwatch.ElapsedMicroseconds(); + long handlingTimeMicroseconds = (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds; _ = _jsonRpcLocalStats.ReportCall(new RpcReport("# collection serialization #", handlingTimeMicroseconds, true), handlingTimeMicroseconds, singleResponseSize); } else { - long handlingTimeMicroseconds = stopwatch.ElapsedMicroseconds(); + long handlingTimeMicroseconds = (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds; _ = _jsonRpcLocalStats.ReportCall(result.Report!.Value, handlingTimeMicroseconds, singleResponseSize); } - stopwatch.Restart(); + startTime = Stopwatch.GetTimestamp(); } } diff --git a/src/Nethermind/Nethermind.Merge.Plugin/EngineRpcModule.Paris.cs b/src/Nethermind/Nethermind.Merge.Plugin/EngineRpcModule.Paris.cs index f5c0616b826..4cf84584a76 100644 --- a/src/Nethermind/Nethermind.Merge.Plugin/EngineRpcModule.Paris.cs +++ b/src/Nethermind/Nethermind.Merge.Plugin/EngineRpcModule.Paris.cs @@ -41,15 +41,14 @@ protected async Task> ForkchoiceUpdated { if (await _locker.WaitAsync(_timeout)) { - Stopwatch watch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); try { return await _forkchoiceUpdatedV1Handler.Handle(forkchoiceState, payloadAttributes, version); } finally { - watch.Stop(); - Metrics.ForkchoiceUpdedExecutionTime = watch.ElapsedMilliseconds; + Metrics.ForkchoiceUpdedExecutionTime = (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds; _locker.Release(); } } @@ -82,7 +81,7 @@ protected async Task> NewPayload(IExecutionPayloa if (await _locker.WaitAsync(_timeout)) { - Stopwatch watch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); try { using IDisposable region = _gcKeeper.TryStartNoGCRegion(); @@ -95,8 +94,7 @@ protected async Task> NewPayload(IExecutionPayloa } finally { - watch.Stop(); - Metrics.NewPayloadExecutionTime = watch.ElapsedMilliseconds; + Metrics.NewPayloadExecutionTime = (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds; _locker.Release(); } } diff --git a/src/Nethermind/Nethermind.Merge.Plugin/Synchronization/MergeBlockDownloader.cs b/src/Nethermind/Nethermind.Merge.Plugin/Synchronization/MergeBlockDownloader.cs index 1091473ca26..f0768e39168 100644 --- a/src/Nethermind/Nethermind.Merge.Plugin/Synchronization/MergeBlockDownloader.cs +++ b/src/Nethermind/Nethermind.Merge.Plugin/Synchronization/MergeBlockDownloader.cs @@ -179,7 +179,7 @@ bool HasMoreToSync(out BlockHeader[]? headers, out int headersToRequest) if (cancellation.IsCancellationRequested) return blocksSynced; // check before every heavy operation - Stopwatch sw = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); await RequestBodies(bestPeer, cancellation, context); if (downloadReceipts) @@ -189,7 +189,7 @@ bool HasMoreToSync(out BlockHeader[]? headers, out int headersToRequest) await RequestReceipts(bestPeer, cancellation, context); } - AdjustSyncBatchSize(sw.Elapsed); + AdjustSyncBatchSize(Stopwatch.GetElapsedTime(startTime)); blocks = context.Blocks; receipts = context.ReceiptsForBlocks; diff --git a/src/Nethermind/Nethermind.Network.Discovery.Test/DiscoveryManagerTests.cs b/src/Nethermind/Nethermind.Network.Discovery.Test/DiscoveryManagerTests.cs index f6d36407232..7921d946c1c 100644 --- a/src/Nethermind/Nethermind.Network.Discovery.Test/DiscoveryManagerTests.cs +++ b/src/Nethermind/Nethermind.Network.Discovery.Test/DiscoveryManagerTests.cs @@ -200,7 +200,7 @@ public async Task RateLimitOutgoingMessage() MaxOutgoingMessagePerSecond = 5 }); - Stopwatch sw = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); FindNodeMsg msg = new(_publicKey, 0, Array.Empty()); await _discoveryManager.SendMessageAsync(msg); await _discoveryManager.SendMessageAsync(msg); @@ -208,7 +208,7 @@ public async Task RateLimitOutgoingMessage() await _discoveryManager.SendMessageAsync(msg); await _discoveryManager.SendMessageAsync(msg); await _discoveryManager.SendMessageAsync(msg); - sw.Elapsed.Should().BeGreaterOrEqualTo(TimeSpan.FromSeconds(0.9)); + Stopwatch.GetElapsedTime(startTime).Should().BeGreaterOrEqualTo(TimeSpan.FromSeconds(0.9)); } } } diff --git a/src/Nethermind/Nethermind.Network.Dns.Test/EnrDiscoveryTests.cs b/src/Nethermind/Nethermind.Network.Dns.Test/EnrDiscoveryTests.cs index fb20bb43b14..0c5dc4143ed 100644 --- a/src/Nethermind/Nethermind.Network.Dns.Test/EnrDiscoveryTests.cs +++ b/src/Nethermind/Nethermind.Network.Dns.Test/EnrDiscoveryTests.cs @@ -33,10 +33,10 @@ public async Task Test_enr_discovery(string url) INetworkConfig config = new NetworkConfig(); config.DiscoveryDns = url; EnrDiscovery enrDiscovery = new(new EnrRecordParser(singer), config, testErrorLogManager); - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); List addedRecords = enrDiscovery.DiscoverNodes(default).ToBlockingEnumerable().ToList(); - await TestContext.Out.WriteLineAsync($"Actually added {addedRecords.Count} in {stopwatch.Elapsed:g}"); + await TestContext.Out.WriteLineAsync($"Actually added {addedRecords.Count} in {Stopwatch.GetElapsedTime(startTime):g}"); foreach (TestErrorLogManager.Error error in testErrorLogManager.Errors) { await TestContext.Out.WriteLineAsync(error.Text); diff --git a/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/P2PProtocolHandler.cs b/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/P2PProtocolHandler.cs index e5a3db6b9d6..b0c3c5d1615 100644 --- a/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/P2PProtocolHandler.cs +++ b/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/P2PProtocolHandler.cs @@ -271,7 +271,7 @@ public async Task SendPing() if (Logger.IsTrace) Logger.Trace($"{Session} P2P sending ping on {Session.RemotePort} ({RemoteClientId})"); Send(PingMessage.Instance); _nodeStatsManager.ReportEvent(Session.Node, NodeStatsEventType.P2PPingOut); - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); CancellationTokenSource delayCancellation = new(); try @@ -286,7 +286,7 @@ public async Task SendPing() return false; } - long latency = stopwatch.ElapsedMilliseconds; + long latency = (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds; _nodeStatsManager.ReportTransferSpeedEvent(Session.Node, TransferSpeedType.Latency, latency); return true; } diff --git a/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs b/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs index b47db24a5ac..29c818f1e51 100644 --- a/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs +++ b/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs @@ -283,7 +283,7 @@ private void SendMessage(IOwnedReadOnlyList txsToSend) protected async Task Handle(GetBlockHeadersMessage getBlockHeadersMessage, CancellationToken cancellationToken) { using GetBlockHeadersMessage message = getBlockHeadersMessage; - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); if (Logger.IsTrace) { Logger.Trace($"Received headers request from {Session.Node:c}:"); @@ -309,8 +309,7 @@ protected async Task Handle(GetBlockHeadersMessage getBlock // } BlockHeadersMessage resp = await FulfillBlockHeadersRequest(message, cancellationToken); - stopwatch.Stop(); - if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockHeaders to {Node:c} in {stopwatch.Elapsed.TotalMilliseconds}ms"); + if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockHeaders to {Node:c} in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); return resp; } @@ -343,12 +342,11 @@ protected async Task Handle(GetBlockBodiesMessage request, C Logger.Trace($"Received bodies request of length {message.BlockHashes.Count} from {Session.Node:c}:"); } - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); Interlocked.Increment(ref Counter); BlockBodiesMessage resp = await FulfillBlockBodiesRequest(message, cancellationToken); - stopwatch.Stop(); - if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockBodies to {Node:c} in {stopwatch.Elapsed.TotalMilliseconds}ms"); + if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockBodies to {Node:c} in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); return resp; } @@ -391,10 +389,9 @@ protected async Task Handle(GetReceiptsMessage msg, Cancellatio throw new EthSyncException("Incoming receipts request for more than 512 blocks"); } - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); ReceiptsMessage resp = await FulfillReceiptsRequest(message, cancellationToken); - stopwatch.Stop(); - if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} Receipts to {Node:c} in {stopwatch.Elapsed.TotalMilliseconds}ms"); + if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} Receipts to {Node:c} in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); return resp; } diff --git a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs index be1d225effb..8a7ae6b50f1 100644 --- a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs +++ b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs @@ -106,10 +106,9 @@ private async Task Handle(GetNodeDataMessage msg, CancellationT { using var message = msg; - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); NodeDataMessage response = await FulfillNodeDataRequest(message, cancellationToken); - stopwatch.Stop(); - if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} NodeData to {Node:c} in {stopwatch.Elapsed.TotalMilliseconds}ms"); + if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} NodeData to {Node:c} in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); return response; } diff --git a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs index a15a71193f5..c66a4bee8cc 100644 --- a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs +++ b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs @@ -97,15 +97,14 @@ protected virtual void Handle(NewPooledTransactionHashesMessage msg) using var _ = msg; AddNotifiedTransactions(msg.Hashes); - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); TxPool.Metrics.PendingTransactionsHashesReceived += msg.Hashes.Count; _pooledTxsRequestor.RequestTransactions(Send, msg.Hashes); - stopwatch.Stop(); if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} {nameof(NewPooledTransactionHashesMessage)} to {Node:c} " + - $"in {stopwatch.Elapsed.TotalMilliseconds}ms"); + $"in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } protected void AddNotifiedTransactions(IReadOnlyList hashes) @@ -119,12 +118,11 @@ protected void AddNotifiedTransactions(IReadOnlyList hashes) private async ValueTask Handle(GetPooledTransactionsMessage msg, CancellationToken cancellationToken) { using var message = msg; - var stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); Send(await FulfillPooledTransactionsRequest(message, cancellationToken)); - stopwatch.Stop(); if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} {nameof(GetPooledTransactionsMessage)} to {Node:c} " + - $"in {stopwatch.Elapsed.TotalMilliseconds}ms"); + $"in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } internal Task FulfillPooledTransactionsRequest(GetPooledTransactionsMessage msg, CancellationToken cancellationToken) diff --git a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs index 95595b3b5c0..fee511e9a3f 100644 --- a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs +++ b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs @@ -194,15 +194,14 @@ protected override void Handle(NewPooledTransactionHashesMessage msg) { using var message = msg; bool isTrace = Logger.IsTrace; - Stopwatch? stopwatch = isTrace ? Stopwatch.StartNew() : null; + long startTime = isTrace ? Stopwatch.GetTimestamp() : 0; TxPool.Metrics.PendingTransactionsHashesReceived += message.Hashes.Count; _pooledTxsRequestor.RequestTransactionsEth66(_sendAction, message.Hashes); - stopwatch?.Stop(); if (isTrace) Logger.Trace($"OUT {Counter:D5} {nameof(NewPooledTransactionHashesMessage)} to {Node:c} " + - $"in {stopwatch.Elapsed.TotalMilliseconds}ms"); + $"in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } protected override async Task> SendRequest(V62.Messages.GetBlockHeadersMessage message, CancellationToken token) diff --git a/src/Nethermind/Nethermind.Runner/JsonRpc/Startup.cs b/src/Nethermind/Nethermind.Runner/JsonRpc/Startup.cs index f3c29b1fed8..7e970cda02d 100644 --- a/src/Nethermind/Nethermind.Runner/JsonRpc/Startup.cs +++ b/src/Nethermind/Nethermind.Runner/JsonRpc/Startup.cs @@ -163,7 +163,7 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, IJsonRpc if (jsonRpcUrl.MaxRequestBodySize is not null) ctx.Features.Get().MaxRequestBodySize = jsonRpcUrl.MaxRequestBodySize; - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); CountingPipeReader request = new(ctx.Request.BodyReader); try { @@ -243,7 +243,7 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, IJsonRpc await ctx.Response.CompleteAsync(); } - long handlingTimeMicroseconds = stopwatch.ElapsedMicroseconds(); + long handlingTimeMicroseconds = (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds; _ = jsonRpcLocalStats.ReportCall(result.IsCollection ? new RpcReport("# collection serialization #", handlingTimeMicroseconds, true) : result.Report.Value, handlingTimeMicroseconds, resultWriter.WrittenCount); diff --git a/src/Nethermind/Nethermind.Runner/Program.cs b/src/Nethermind/Nethermind.Runner/Program.cs index e6d0b5780a0..a5b51eea045 100644 --- a/src/Nethermind/Nethermind.Runner/Program.cs +++ b/src/Nethermind/Nethermind.Runner/Program.cs @@ -412,11 +412,10 @@ private static IConfigProvider BuildConfigProvider( else { _logger.Info($"Loading standard NLog.config file from {"NLog.config".GetApplicationResourcePath()}."); - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); LogManager.Configuration = new XmlLoggingConfiguration("NLog.config".GetApplicationResourcePath()); - stopwatch.Stop(); - _logger.Info($"NLog.config loaded in {stopwatch.ElapsedMilliseconds}ms."); + _logger.Info($"NLog.config loaded in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms."); } // TODO: dynamically switch log levels from CLI! diff --git a/src/Nethermind/Nethermind.Synchronization/Blocks/BlockDownloader.cs b/src/Nethermind/Nethermind.Synchronization/Blocks/BlockDownloader.cs index 765c0f7e7a4..77f78aa7420 100644 --- a/src/Nethermind/Nethermind.Synchronization/Blocks/BlockDownloader.cs +++ b/src/Nethermind/Nethermind.Synchronization/Blocks/BlockDownloader.cs @@ -167,7 +167,7 @@ bool HasMoreToSync() } if (_logger.IsDebug) _logger.Debug($"Headers request {currentNumber}+{headersToRequest} to peer {bestPeer} with {bestPeer.HeadNumber} blocks. Got {currentNumber} and asking for {headersToRequest} more."); - Stopwatch sw = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); using IOwnedReadOnlyList headers = await RequestHeaders(bestPeer, cancellation, currentNumber, headersToRequest); Hash256? startHeaderHash = headers[0]?.Hash; @@ -188,7 +188,7 @@ bool HasMoreToSync() } ancestorLookupLevel = 0; - AdjustSyncBatchSize(sw.Elapsed); + AdjustSyncBatchSize(Stopwatch.GetElapsedTime(startTime)); for (int i = 1; i < headers.Count; i++) { diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/PendingSyncItems.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/PendingSyncItems.cs index 2cd79d10912..55d71f0759a 100644 --- a/src/Nethermind/Nethermind.Synchronization/FastSync/PendingSyncItems.cs +++ b/src/Nethermind/Nethermind.Synchronization/FastSync/PendingSyncItems.cs @@ -202,7 +202,7 @@ public List TakeBatch(int maxSize) [MethodImpl(MethodImplOptions.Synchronized)] public string RecalculatePriorities() { - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); string reviewMessage = $"Node sync queues review ({LevelsDescription}):" + Environment.NewLine; reviewMessage += $" before {Description}" + Environment.NewLine; @@ -225,8 +225,7 @@ public string RecalculatePriorities() reviewMessage += $" after {Description}" + Environment.NewLine; - stopwatch.Stop(); - reviewMessage += $" time spent in review: {stopwatch.ElapsedMilliseconds}ms"; + reviewMessage += $" time spent in review: {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"; return reviewMessage; } } diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/TreeSync.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/TreeSync.cs index 4cc449cb47b..89948d4c4c9 100644 --- a/src/Nethermind/Nethermind.Synchronization/FastSync/TreeSync.cs +++ b/src/Nethermind/Nethermind.Synchronization/FastSync/TreeSync.cs @@ -167,7 +167,7 @@ void AddAgainAllItems() if (_logger.IsDebug) _logger.Debug(reviewMessage); } - Stopwatch handleWatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); bool isMissingRequestData = batch.RequestedNodes is null; if (isMissingRequestData) @@ -289,24 +289,23 @@ shorter than the request */ _data.DisplayProgressReport(_pendingRequests.Count, _branchProgress, _logger); - handleWatch.Stop(); - long total = handleWatch.ElapsedMilliseconds + _networkWatch.ElapsedMilliseconds; + long total = (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds + _networkWatch.ElapsedMilliseconds; if (total != 0) { // calculate averages if (_logger.IsTrace) _logger.Trace( - $"Prepare batch {_networkWatch.ElapsedMilliseconds}ms ({(decimal)_networkWatch.ElapsedMilliseconds / total:P0}) - Handle {handleWatch.ElapsedMilliseconds}ms ({(decimal)handleWatch.ElapsedMilliseconds / total:P0})"); + $"Prepare batch {_networkWatch.ElapsedMilliseconds}ms ({(decimal)_networkWatch.ElapsedMilliseconds / total:P0}) - Handle {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms ({(decimal)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds / total:P0})"); } - if (handleWatch.ElapsedMilliseconds > 250) + if (Stopwatch.GetElapsedTime(startTime).TotalMilliseconds > 250) { if (_logger.IsDebug) _logger.Debug( - $"Handle watch {handleWatch.ElapsedMilliseconds}, DB reads {_data.DbChecks - _data.LastDbReads}, ratio {(decimal)handleWatch.ElapsedMilliseconds / Math.Max(1, _data.DbChecks - _data.LastDbReads)}"); + $"Handle watch {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}, DB reads {_data.DbChecks - _data.LastDbReads}, ratio {(decimal)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds / Math.Max(1, _data.DbChecks - _data.LastDbReads)}"); } - Interlocked.Add(ref _handleWatch, handleWatch.ElapsedMilliseconds); + Interlocked.Add(ref _handleWatch, (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds); _data.LastDbReads = _data.DbChecks; _data.AverageTimeInHandler = _handleWatch / (decimal)_data.ProcessedRequestsCount; diff --git a/src/Nethermind/Nethermind.TxPool/Collections/PersistentBlobTxDistinctSortedPool.cs b/src/Nethermind/Nethermind.TxPool/Collections/PersistentBlobTxDistinctSortedPool.cs index d0f7eb34d92..fc6640658a6 100644 --- a/src/Nethermind/Nethermind.TxPool/Collections/PersistentBlobTxDistinctSortedPool.cs +++ b/src/Nethermind/Nethermind.TxPool/Collections/PersistentBlobTxDistinctSortedPool.cs @@ -33,7 +33,7 @@ private void RecreateLightTxCollectionAndCache(ITxStorage blobTxStorage) if (_logger.IsDebug) _logger.Debug("Recreating light collection of blob transactions and cache"); int numberOfTxsInDb = 0; int numberOfBlobsInDb = 0; - Stopwatch stopwatch = Stopwatch.StartNew(); + long startTime = Stopwatch.GetTimestamp(); foreach (LightTransaction lightBlobTx in blobTxStorage.GetAll()) { if (base.TryInsert(lightBlobTx.Hash, lightBlobTx, out _)) @@ -46,11 +46,10 @@ private void RecreateLightTxCollectionAndCache(ITxStorage blobTxStorage) if (_logger.IsInfo && numberOfTxsInDb != 0) { - long loadingTime = stopwatch.ElapsedMilliseconds; + long loadingTime = (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds; _logger.Info($"Loaded {numberOfTxsInDb} blob txs from persistent db, containing {numberOfBlobsInDb} blobs, in {loadingTime}ms"); _logger.Info($"There are {BlobIndex.Count} unique blobs indexed"); } - stopwatch.Stop(); } public override bool TryInsert(ValueHash256 hash, Transaction fullBlobTx, out Transaction? removed) From 4b8c86480ef42ef923f6fca2621f48eee645bc6b Mon Sep 17 00:00:00 2001 From: Shubham Sonthalia Date: Sat, 5 Oct 2024 17:37:01 +0530 Subject: [PATCH 2/3] remaining changes --- .../P2P/Subprotocols/Eth/V68/Eth68ProtocolHandler.cs | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V68/Eth68ProtocolHandler.cs b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V68/Eth68ProtocolHandler.cs index 15c0ace7a19..ffdd30c9d0f 100644 --- a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V68/Eth68ProtocolHandler.cs +++ b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V68/Eth68ProtocolHandler.cs @@ -94,13 +94,11 @@ private void Handle(NewPooledTransactionHashesMessage68 msg) AddNotifiedTransactions(message.Hashes); - Stopwatch? stopwatch = isTrace ? Stopwatch.StartNew() : null; + long startTime = isTrace ? Stopwatch.GetTimestamp() : 0; _pooledTxsRequestor.RequestTransactionsEth68(_sendAction, message.Hashes, message.Sizes, message.Types); - stopwatch?.Stop(); - - if (isTrace) Logger.Trace($"OUT {Counter:D5} {nameof(NewPooledTransactionHashesMessage68)} to {Node:c} in {stopwatch.Elapsed.TotalMilliseconds}ms"); + if (isTrace) Logger.Trace($"OUT {Counter:D5} {nameof(NewPooledTransactionHashesMessage68)} to {Node:c} in { Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } protected override void SendNewTransactionCore(Transaction tx) From b477517451033dfbf2e8b848597bdbc540094ca9 Mon Sep 17 00:00:00 2001 From: Shubham Sonthalia Date: Sun, 6 Oct 2024 10:00:41 +0530 Subject: [PATCH 3/3] Converting GetElapsedTime to long while logging and string formatting --- src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs | 2 +- .../Nethermind.Init/Steps/EthereumStepsManager.cs | 6 +++--- src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs | 2 +- src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs | 6 +++--- .../P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs | 6 +++--- .../P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs | 2 +- .../P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs | 4 ++-- .../P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs | 2 +- src/Nethermind/Nethermind.Runner/Program.cs | 2 +- .../Nethermind.Synchronization/FastSync/PendingSyncItems.cs | 2 +- .../Nethermind.Synchronization/FastSync/TreeSync.cs | 4 ++-- 11 files changed, 19 insertions(+), 19 deletions(-) diff --git a/src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs b/src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs index c4c2db39e12..79c2c66667e 100644 --- a/src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs +++ b/src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs @@ -94,7 +94,7 @@ private async Task ProcessRequestAsync(Method method, string endpoint, str if (_logger.IsError) _logger.Error($"Unsupported HTTP method: {methodType}."); return default; } - if (_logger.IsTrace) _logger.Trace($"Received HTTP {methodType} response from: {endpoint} [id: {requestId}, elapsed: {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds} ms]: {response}"); + if (_logger.IsTrace) _logger.Trace($"Received HTTP {methodType} response from: {endpoint} [id: {requestId}, elapsed: {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds} ms]: {response}"); if (!response.IsSuccessStatusCode) { return default; diff --git a/src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs b/src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs index 1535e6fbe4d..a1bd881c078 100644 --- a/src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs +++ b/src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs @@ -154,7 +154,7 @@ private async Task ExecuteStep(IStep step, StepInfo stepInfo, CancellationToken if (_logger.IsDebug) _logger.Debug( - $"Step {step.GetType().Name.PadRight(24)} executed in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + $"Step {step.GetType().Name.PadRight(24)} executed in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); stepInfo.Stage = StepInitializationStage.Complete; } @@ -164,7 +164,7 @@ private async Task ExecuteStep(IStep step, StepInfo stepInfo, CancellationToken { if (_logger.IsError) _logger.Error( - $"Step {step.GetType().Name.PadRight(24)} failed after {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms", + $"Step {step.GetType().Name.PadRight(24)} failed after {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms", exception); stepInfo.Stage = StepInitializationStage.Failed; @@ -174,7 +174,7 @@ private async Task ExecuteStep(IStep step, StepInfo stepInfo, CancellationToken if (_logger.IsWarn) { _logger.Warn( - $"Step {step.GetType().Name.PadRight(24)} failed after {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms {exception}"); + $"Step {step.GetType().Name.PadRight(24)} failed after {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms {exception}"); } stepInfo.Stage = StepInitializationStage.Complete; } diff --git a/src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs b/src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs index e1126725b2e..e23362a4a81 100644 --- a/src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs +++ b/src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs @@ -33,7 +33,7 @@ public async Task Execute(CancellationToken cancellationToken) long startTime = Stopwatch.GetTimestamp(); await plugin.Init(_api); if (logger.IsInfo) - logger.Info($" {plugin.Name} by {plugin.Author} initialized in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + logger.Info($" {plugin.Name} by {plugin.Author} initialized in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } catch (Exception e) { diff --git a/src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs b/src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs index 2c2d448e635..3100101c257 100644 --- a/src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs +++ b/src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs @@ -231,7 +231,7 @@ JsonRpcResult GetParsingError(string error, Exception? exception = null) errorResponse.AddDisposable(() => jsonDocument.Dispose()); TraceResult(errorResponse); - if (_logger.IsDebug) _logger.Debug($" Failed request handled in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + if (_logger.IsDebug) _logger.Debug($" Failed request handled in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); deserializationFailureResult = JsonRpcResult.Single(RecordResponse(errorResponse, new RpcReport("# parsing error #",(long) Stopwatch.GetElapsedTime(startTime).TotalMilliseconds, false))); yield return deserializationFailureResult.Value; break; @@ -320,7 +320,7 @@ static bool HasNonWhitespace(ReadOnlySpan span) yield return RecordResponse(response); } - if (_logger.IsDebug) _logger.Debug($" {requests.Count} requests handled in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + if (_logger.IsDebug) _logger.Debug($" {requests.Count} requests handled in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } finally { @@ -351,7 +351,7 @@ static bool HasNonWhitespace(ReadOnlySpan span) } - if (_logger.IsDebug) _logger.Debug($" {request} handled in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + if (_logger.IsDebug) _logger.Debug($" {request} handled in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); JsonRpcResult.Entry result = new(response, new RpcReport(request.Method, (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds, isSuccess)); TraceResult(result); diff --git a/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs b/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs index 29c818f1e51..cd0545346e8 100644 --- a/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs +++ b/src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs @@ -309,7 +309,7 @@ protected async Task Handle(GetBlockHeadersMessage getBlock // } BlockHeadersMessage resp = await FulfillBlockHeadersRequest(message, cancellationToken); - if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockHeaders to {Node:c} in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockHeaders to {Node:c} in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); return resp; } @@ -346,7 +346,7 @@ protected async Task Handle(GetBlockBodiesMessage request, C Interlocked.Increment(ref Counter); BlockBodiesMessage resp = await FulfillBlockBodiesRequest(message, cancellationToken); - if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockBodies to {Node:c} in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockBodies to {Node:c} in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); return resp; } @@ -391,7 +391,7 @@ protected async Task Handle(GetReceiptsMessage msg, Cancellatio long startTime = Stopwatch.GetTimestamp(); ReceiptsMessage resp = await FulfillReceiptsRequest(message, cancellationToken); - if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} Receipts to {Node:c} in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} Receipts to {Node:c} in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); return resp; } diff --git a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs index 8a7ae6b50f1..eeac5e2ef00 100644 --- a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs +++ b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs @@ -108,7 +108,7 @@ private async Task Handle(GetNodeDataMessage msg, CancellationT long startTime = Stopwatch.GetTimestamp(); NodeDataMessage response = await FulfillNodeDataRequest(message, cancellationToken); - if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} NodeData to {Node:c} in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} NodeData to {Node:c} in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); return response; } diff --git a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs index c66a4bee8cc..5d9f82776a9 100644 --- a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs +++ b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs @@ -104,7 +104,7 @@ protected virtual void Handle(NewPooledTransactionHashesMessage msg) if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} {nameof(NewPooledTransactionHashesMessage)} to {Node:c} " + - $"in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + $"in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } protected void AddNotifiedTransactions(IReadOnlyList hashes) @@ -122,7 +122,7 @@ private async ValueTask Handle(GetPooledTransactionsMessage msg, CancellationTok Send(await FulfillPooledTransactionsRequest(message, cancellationToken)); if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} {nameof(GetPooledTransactionsMessage)} to {Node:c} " + - $"in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + $"in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } internal Task FulfillPooledTransactionsRequest(GetPooledTransactionsMessage msg, CancellationToken cancellationToken) diff --git a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs index fee511e9a3f..c76cae14f93 100644 --- a/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs +++ b/src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs @@ -201,7 +201,7 @@ protected override void Handle(NewPooledTransactionHashesMessage msg) if (isTrace) Logger.Trace($"OUT {Counter:D5} {nameof(NewPooledTransactionHashesMessage)} to {Node:c} " + - $"in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); + $"in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"); } protected override async Task> SendRequest(V62.Messages.GetBlockHeadersMessage message, CancellationToken token) diff --git a/src/Nethermind/Nethermind.Runner/Program.cs b/src/Nethermind/Nethermind.Runner/Program.cs index a5b51eea045..51a0dccf5b8 100644 --- a/src/Nethermind/Nethermind.Runner/Program.cs +++ b/src/Nethermind/Nethermind.Runner/Program.cs @@ -415,7 +415,7 @@ private static IConfigProvider BuildConfigProvider( long startTime = Stopwatch.GetTimestamp(); LogManager.Configuration = new XmlLoggingConfiguration("NLog.config".GetApplicationResourcePath()); - _logger.Info($"NLog.config loaded in {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms."); + _logger.Info($"NLog.config loaded in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms."); } // TODO: dynamically switch log levels from CLI! diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/PendingSyncItems.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/PendingSyncItems.cs index 55d71f0759a..c2a7030c01c 100644 --- a/src/Nethermind/Nethermind.Synchronization/FastSync/PendingSyncItems.cs +++ b/src/Nethermind/Nethermind.Synchronization/FastSync/PendingSyncItems.cs @@ -225,7 +225,7 @@ public string RecalculatePriorities() reviewMessage += $" after {Description}" + Environment.NewLine; - reviewMessage += $" time spent in review: {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"; + reviewMessage += $" time spent in review: {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms"; return reviewMessage; } } diff --git a/src/Nethermind/Nethermind.Synchronization/FastSync/TreeSync.cs b/src/Nethermind/Nethermind.Synchronization/FastSync/TreeSync.cs index 89948d4c4c9..7f8c32e384f 100644 --- a/src/Nethermind/Nethermind.Synchronization/FastSync/TreeSync.cs +++ b/src/Nethermind/Nethermind.Synchronization/FastSync/TreeSync.cs @@ -295,14 +295,14 @@ shorter than the request */ // calculate averages if (_logger.IsTrace) _logger.Trace( - $"Prepare batch {_networkWatch.ElapsedMilliseconds}ms ({(decimal)_networkWatch.ElapsedMilliseconds / total:P0}) - Handle {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms ({(decimal)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds / total:P0})"); + $"Prepare batch {_networkWatch.ElapsedMilliseconds}ms ({(decimal)_networkWatch.ElapsedMilliseconds / total:P0}) - Handle {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms ({(decimal)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds / total:P0})"); } if (Stopwatch.GetElapsedTime(startTime).TotalMilliseconds > 250) { if (_logger.IsDebug) _logger.Debug( - $"Handle watch {Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}, DB reads {_data.DbChecks - _data.LastDbReads}, ratio {(decimal)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds / Math.Max(1, _data.DbChecks - _data.LastDbReads)}"); + $"Handle watch {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}, DB reads {_data.DbChecks - _data.LastDbReads}, ratio {(decimal)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds / Math.Max(1, _data.DbChecks - _data.LastDbReads)}"); } Interlocked.Add(ref _handleWatch, (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds);