7553 get elapsed time refactoring

src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs

@@ -94,7 +94,7 @@ private async Task<T> ProcessRequestAsync<T>(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: {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds} ms]: {response}");
+            if (_logger.IsTrace) _logger.Trace($"Received HTTP {methodType} response from: {endpoint} [id: {requestId}, elapsed: {String.Format("{0:N0}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)} ms]: {response}");
             if (!response.IsSuccessStatusCode)
             {
                 return default;

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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+                        $"Step {step.GetType().Name.PadRight(24)} executed in {String.Format("{{0:N0}}", (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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms",
+                            $"Step {step.GetType().Name.PadRight(24)} failed after {String.Format("{{0:N0}}", (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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms {exception}");
+                        $"Step {step.GetType().Name.PadRight(24)} failed after {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms {exception}");
                 }
                 stepInfo.Stage = StepInitializationStage.Complete;
             }

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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+                        logger.Info($"  {plugin.Name} by {plugin.Author} initialized in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
                 }
                 catch (Exception e)
                 {

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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+                    if (_logger.IsDebug) _logger.Debug($"  Failed request handled in {String.Format("{{0:N0}}", (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<byte> span)
                 yield return RecordResponse(response);
             }
 
-            if (_logger.IsDebug) _logger.Debug($"  {requests.Count} requests handled in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+            if (_logger.IsDebug) _logger.Debug($"  {requests.Count} requests handled in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
         }
         finally
         {
@@ -351,7 +351,7 @@ static bool HasNonWhitespace(ReadOnlySpan<byte> span)
         }
 
 
-        if (_logger.IsDebug) _logger.Debug($"  {request} handled in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+        if (_logger.IsDebug) _logger.Debug($"  {request} handled in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
 
         JsonRpcResult.Entry result = new(response, new RpcReport(request.Method, (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds, isSuccess));
         TraceResult(result);

src/Nethermind/Nethermind.JsonRpc/WebSockets/JsonRpcSocketsClient.cs

@@ -58,7 +58,6 @@ public override void Dispose()
 
     public override async Task ProcessAsync(ArraySegment<byte> data)
     {
-        long startTime = Stopwatch.GetTimestamp();
         IncrementBytesReceivedMetric(data.Count);
         PipeReader request = PipeReader.Create(new ReadOnlySequence<byte>(data.Array!, data.Offset, data.Count));
         int allResponsesSize = 0;
@@ -67,11 +66,12 @@ public override async Task ProcessAsync(ArraySegment<byte> data)
         {
             using (result)
             {
-                startTime = Stopwatch.GetTimestamp();
-
+
                 int singleResponseSize = await SendJsonRpcResult(result);
                 allResponsesSize += singleResponseSize;
 
+                long startTime = Stopwatch.GetTimestamp();
+
                 if (result.IsCollection)
                 {
                     long handlingTimeMicroseconds = (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds;
@@ -82,8 +82,6 @@ public override async Task ProcessAsync(ArraySegment<byte> data)
                     long handlingTimeMicroseconds = (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds;
                     _ = _jsonRpcLocalStats.ReportCall(result.Report!.Value, handlingTimeMicroseconds, singleResponseSize);
                 }
-
-                startTime = Stopwatch.GetTimestamp();
             }
         }
 

src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/SyncPeerProtocolHandlerBase.cs

@@ -309,7 +309,7 @@ protected async Task<BlockHeadersMessage> Handle(GetBlockHeadersMessage getBlock
             // }
 
             BlockHeadersMessage resp = await FulfillBlockHeadersRequest(message, cancellationToken);
-            if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockHeaders to {Node:c} in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+            if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockHeaders to {Node:c} in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
 
             return resp;
         }
@@ -346,7 +346,7 @@ protected async Task<BlockBodiesMessage> 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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+            if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} BlockBodies to {Node:c} in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
             return resp;
         }
 
@@ -391,7 +391,7 @@ protected async Task<ReceiptsMessage> 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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+            if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} Receipts to {Node:c} in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
 
             return resp;
         }

src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V63/Eth63ProtocolHandler.cs

@@ -108,7 +108,7 @@ private async Task<NodeDataMessage> 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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+            if (Logger.IsTrace) Logger.Trace($"OUT {Counter:D5} NodeData to {Node:c} in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
 
             return response;
         }

src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V65/Eth65ProtocolHandler.cs

@@ -1,6 +1,7 @@
 // SPDX-FileCopyrightText: 2022 Demerzel Solutions Limited
 // SPDX-License-Identifier: LGPL-3.0-only
 
+using System;
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Threading;
@@ -104,7 +105,7 @@ protected virtual void Handle(NewPooledTransactionHashesMessage msg)
 
             if (Logger.IsTrace)
                 Logger.Trace($"OUT {Counter:D5} {nameof(NewPooledTransactionHashesMessage)} to {Node:c} " +
-                             $"in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+                             $"in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
         }
 
         protected void AddNotifiedTransactions(IReadOnlyList<Hash256> hashes)
@@ -122,7 +123,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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+                             $"in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
         }
 
         internal Task<PooledTransactionsMessage> FulfillPooledTransactionsRequest(GetPooledTransactionsMessage msg, CancellationToken cancellationToken)

src/Nethermind/Nethermind.Network/P2P/Subprotocols/Eth/V66/Eth66ProtocolHandler.cs

@@ -194,14 +194,14 @@ protected override void Handle(NewPooledTransactionHashesMessage msg)
         {
             using var message = msg;
             bool isTrace = Logger.IsTrace;
-            long startTime = isTrace ? Stopwatch.GetTimestamp() : 0;
+            long startTime = Stopwatch.GetTimestamp();
 
             TxPool.Metrics.PendingTransactionsHashesReceived += message.Hashes.Count;
             _pooledTxsRequestor.RequestTransactionsEth66(_sendAction, message.Hashes);
 
             if (isTrace)
                 Logger.Trace($"OUT {Counter:D5} {nameof(NewPooledTransactionHashesMessage)} to {Node:c} " +
-                             $"in {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
+                             $"in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms");
         }
 
         protected override async Task<IOwnedReadOnlyList<BlockHeader>> SendRequest(V62.Messages.GetBlockHeadersMessage message, CancellationToken token)

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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms.");
+            _logger.Info($"NLog.config loaded in {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms.");
         }
 
         // TODO: dynamically switch log levels from CLI!

src/Nethermind/Nethermind.Synchronization/FastSync/PendingSyncItems.cs

@@ -225,7 +225,7 @@ public string RecalculatePriorities()
 
             reviewMessage += $"  after {Description}" + Environment.NewLine;
 
-            reviewMessage += $"  time spent in review: {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms";
+            reviewMessage += $"  time spent in review: {String.Format("{{0:N0}}", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds)}ms";
             return reviewMessage;
         }
     }

src/Nethermind/Nethermind.Synchronization/FastSync/TreeSync.cs

@@ -289,20 +289,22 @@ shorter than the request */
 
                     _data.DisplayProgressReport(_pendingRequests.Count, _branchProgress, _logger);
 
-                    long total = (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds + _networkWatch.ElapsedMilliseconds;
+
+                    long elapsedTime = (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds;
+                    long total = elapsedTime + _networkWatch.ElapsedMilliseconds;
                     if (total != 0)
                     {
                         // calculate averages
                         if (_logger.IsTrace)
                             _logger.Trace(
-                                $"Prepare batch {_networkWatch.ElapsedMilliseconds}ms ({(decimal)_networkWatch.ElapsedMilliseconds / total:P0}) - Handle {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms ({(decimal)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds / total:P0})");
+                                $"Prepare batch {_networkWatch.ElapsedMilliseconds}ms ({(decimal)_networkWatch.ElapsedMilliseconds / total:P0}) - Handle {String.Format("{{0:N0}}", elapsedTime)}ms ({(decimal)elapsedTime / total:P0})");
                     }
 
                     if (Stopwatch.GetElapsedTime(startTime).TotalMilliseconds > 250)
                     {
                         if (_logger.IsDebug)
                             _logger.Debug(
-                                $"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)}");
+                                $"Handle watch {String.Format("{{0:N0}}", elapsedTime)}, DB reads {_data.DbChecks - _data.LastDbReads}, ratio {(decimal)elapsedTime / Math.Max(1, _data.DbChecks - _data.LastDbReads)}");
                     }
 
                     Interlocked.Add(ref _handleWatch, (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds);