Skip to content

Commit

Permalink
7553 get elapsed time refactoring (#7558)
Browse files Browse the repository at this point in the history
  • Loading branch information
@ssonthal
ssonthal authored Oct 7, 2024
1 parent 99c3dd2 commit dac7890
Show file tree
Hide file tree
Showing 24 changed files with 76 additions and 109 deletions.
12 changes: 4 additions & 8 deletions src/Nethermind/Nethermind.Cli/NodeManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -69,11 +69,9 @@ public async Task<JsValue> PostJint(string method, params object[] parameters)
}
else
{
Stopwatch stopwatch = new();
stopwatch.Start();
long startTime = Stopwatch.GetTimestamp();
object? result = await _currentClient.Post<object>(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)
Expand Down Expand Up @@ -121,11 +119,9 @@ public async Task<JsValue> PostJint(string method, params object[] parameters)
}
else
{
Stopwatch stopwatch = new();
stopwatch.Start();
long starting = Stopwatch.GetTimestamp();
result = await _currentClient.Post<T>(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");
}
}
Expand Down
5 changes: 2 additions & 3 deletions src/Nethermind/Nethermind.Clique.Test/CliqueBlockProducerTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
6 changes: 2 additions & 4 deletions src/Nethermind/Nethermind.Evm.Test/Eip1153Tests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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);
}

/// <summary>
Expand Down
6 changes: 2 additions & 4 deletions src/Nethermind/Nethermind.Facade/Proxy/DefaultHttpClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -79,7 +79,7 @@ private async Task<T> ProcessRequestAsync<T>(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)
{
Expand All @@ -94,9 +94,7 @@ private async Task<T> ProcessRequestAsync<T>(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:N0} ms]: {response}");
if (!response.IsSuccessStatusCode)
{
return default;
Expand Down
9 changes: 4 additions & 5 deletions src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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:N0}ms");

stepInfo.Stage = StepInitializationStage.Complete;
}
Expand All @@ -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:N0}ms",
exception);

stepInfo.Stage = StepInitializationStage.Failed;
Expand All @@ -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:N0}ms {exception}");
}
stepInfo.Stage = StepInitializationStage.Complete;
}
finally
{
stopwatch.Stop();
_autoResetEvent.Set();

if (_logger.IsDebug) _logger.Debug($"{step.GetType().Name.PadRight(24)} complete");
Expand Down
5 changes: 2 additions & 3 deletions src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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:N0}ms");
}
catch (Exception e)
{
Expand Down
24 changes: 9 additions & 15 deletions src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -119,7 +119,7 @@ private ArrayPoolList<JsonRpcRequest> DeserializeArray(JsonElement element) =>
public async IAsyncEnumerable<JsonRpcResult> 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.
Expand All @@ -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.
Expand Down Expand Up @@ -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);
Expand All @@ -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:N0}ms");
deserializationFailureResult = JsonRpcResult.Single(RecordResponse(errorResponse, new RpcReport("# parsing error #", (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds, false)));
yield return deserializationFailureResult.Value;
break;
}
Expand Down Expand Up @@ -304,7 +299,7 @@ static bool HasNonWhitespace(ReadOnlySpan<byte> span)
{
try
{
Stopwatch stopwatch = Stopwatch.StartNew();
long startTime = Stopwatch.GetTimestamp();
int requestIndex = 0;
for (int index = 0; index < requests.Count; index++)
{
Expand All @@ -325,7 +320,7 @@ static bool HasNonWhitespace(ReadOnlySpan<byte> 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:N0}ms");
}
finally
{
Expand All @@ -336,7 +331,7 @@ static bool HasNonWhitespace(ReadOnlySpan<byte> span)
private async Task<JsonRpcResult.Entry> 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;
Expand All @@ -355,11 +350,10 @@ static bool HasNonWhitespace(ReadOnlySpan<byte> 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:N0}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;
}
Expand Down
11 changes: 4 additions & 7 deletions src/Nethermind/Nethermind.JsonRpc/WebSockets/JsonRpcSocketsClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,6 @@ public override void Dispose()

public override async Task ProcessAsync(ArraySegment<byte> data)
{
Stopwatch stopwatch = Stopwatch.StartNew();
IncrementBytesReceivedMetric(data.Count);
PipeReader request = PipeReader.Create(new ReadOnlySequence<byte>(data.Array!, data.Offset, data.Count));
int allResponsesSize = 0;
Expand All @@ -67,23 +66,21 @@ public override async Task ProcessAsync(ArraySegment<byte> data)
{
using (result)
{
stopwatch.Restart();

int singleResponseSize = await SendJsonRpcResult(result);
allResponsesSize += singleResponseSize;

long startTime = Stopwatch.GetTimestamp();

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();
}
}

Expand Down
10 changes: 4 additions & 6 deletions src/Nethermind/Nethermind.Merge.Plugin/EngineRpcModule.Paris.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,15 +41,14 @@ protected async Task<ResultWrapper<ForkchoiceUpdatedV1Result>> 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();
}
}
Expand Down Expand Up @@ -82,7 +81,7 @@ protected async Task<ResultWrapper<PayloadStatusV1>> NewPayload(IExecutionPayloa

if (await _locker.WaitAsync(_timeout))
{
Stopwatch watch = Stopwatch.StartNew();
long startTime = Stopwatch.GetTimestamp();
try
{
using IDisposable region = _gcKeeper.TryStartNoGCRegion();
Expand All @@ -95,8 +94,7 @@ protected async Task<ResultWrapper<PayloadStatusV1>> NewPayload(IExecutionPayloa
}
finally
{
watch.Stop();
Metrics.NewPayloadExecutionTime = watch.ElapsedMilliseconds;
Metrics.NewPayloadExecutionTime = (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds;
_locker.Release();
}
}
Expand Down
4 changes: 2 additions & 2 deletions src/Nethermind/Nethermind.Merge.Plugin/Synchronization/MergeBlockDownloader.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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;
Expand Down
4 changes: 2 additions & 2 deletions src/Nethermind/Nethermind.Network.Discovery.Test/DiscoveryManagerTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -200,15 +200,15 @@ public async Task RateLimitOutgoingMessage()
MaxOutgoingMessagePerSecond = 5
});

Stopwatch sw = Stopwatch.StartNew();
long startTime = Stopwatch.GetTimestamp();
FindNodeMsg msg = new(_publicKey, 0, Array.Empty<byte>());
await _discoveryManager.SendMessageAsync(msg);
await _discoveryManager.SendMessageAsync(msg);
await _discoveryManager.SendMessageAsync(msg);
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));
}
}
}
4 changes: 2 additions & 2 deletions src/Nethermind/Nethermind.Network.Dns.Test/EnrDiscoveryTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<Node> 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);
Expand Down
4 changes: 2 additions & 2 deletions src/Nethermind/Nethermind.Network/P2P/ProtocolHandlers/P2PProtocolHandler.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -271,7 +271,7 @@ public async Task<bool> 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
Expand All @@ -286,7 +286,7 @@ public async Task<bool> SendPing()
return false;
}

long latency = stopwatch.ElapsedMilliseconds;
long latency = (long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds;
_nodeStatsManager.ReportTransferSpeedEvent(Session.Node, TransferSpeedType.Latency, latency);
return true;
}
Expand Down
Loading

0 comments on commit dac7890

Please sign in to comment.