Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

7553 get elapsed time refactoring #7558

Open
wants to merge 4 commits into
base: master
Choose a base branch
from
Open

7553 get elapsed time refactoring #7558

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
e5e4132
Updating stopwatch.startNew logic to startTime in all methods.
ssonthal Oct 5, 2024
4b8c864
remaining changes
ssonthal Oct 5, 2024
b477517
Converting GetElapsedTime to long while logging and string formatting
ssonthal Oct 6, 2024
a31c2a9
Merge branch 'master' into 7553_getElapsedTime_refactoring
ssonthal Oct 6, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 4 additions & 8 deletions src/Nethermind/Nethermind.Cli/NodeManager.cs
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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: {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds} ms]: {response}");
if (!response.IsSuccessStatusCode)
{
return default;
Expand Down
9 changes: 4 additions & 5 deletions src/Nethermind/Nethermind.Init/Steps/EthereumStepsManager.cs
View file
Open in desktop
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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}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 {(long)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");
Expand Down
5 changes: 2 additions & 3 deletions src/Nethermind/Nethermind.Init/Steps/InitializePlugins.cs
View file
Open in desktop
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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}ms");
}
catch (Exception e)
{
Expand Down
24 changes: 9 additions & 15 deletions src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs
View file
Open in desktop
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 {(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;
}
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 {(long)Stopwatch.GetElapsedTime(startTime).TotalMilliseconds}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 {(long)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;
}
Expand Down
10 changes: 5 additions & 5 deletions src/Nethermind/Nethermind.JsonRpc/WebSockets/JsonRpcSocketsClient.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,7 @@ public override void Dispose()

public override async Task ProcessAsync(ArraySegment<byte> data)
{
Stopwatch stopwatch = Stopwatch.StartNew();
long startTime = Stopwatch.GetTimestamp();
IncrementBytesReceivedMetric(data.Count);
PipeReader request = PipeReader.Create(new ReadOnlySequence<byte>(data.Array!, data.Offset, data.Count));
int allResponsesSize = 0;
Expand All @@ -67,23 +67,23 @@ public override async Task ProcessAsync(ArraySegment<byte> 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();
}
}

Expand Down
10 changes: 4 additions & 6 deletions src/Nethermind/Nethermind.Merge.Plugin/EngineRpcModule.Paris.cs
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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