From d320e2ab09998d66c2306c7132dc181e9ee53d95 Mon Sep 17 00:00:00 2001 From: gmega Date: Mon, 27 Nov 2023 12:27:14 -0300 Subject: [PATCH] change enable flag to "chronosProfiling"; add "enable" profiler proc; add stronger assertions to event tests" --- chronos.nimble | 8 ++++ chronos/asyncfutures2.nim | 6 +-- chronos/config.nim | 4 +- chronos/futures.nim | 4 +- chronos/profiler.nim | 28 +++++++++++ chronos/profiler/events.nim | 11 ++++- tests/config.nims | 3 +- tests/profiler/testevents.nim | 12 ++++- tests/profiler/utils.nim | 10 ++-- tests/testall.nim | 2 +- tests/testprofiler.nim | 10 +++- tests/testutils.nim | 87 +++++++++++++++++++++++++++++++++++ 12 files changed, 165 insertions(+), 20 deletions(-) create mode 100644 chronos/profiler.nim create mode 100644 tests/testutils.nim diff --git a/chronos.nimble b/chronos.nimble index 6b4ac58..fd83e7f 100644 --- a/chronos.nimble +++ b/chronos.nimble @@ -48,3 +48,11 @@ task test_libbacktrace, "test with libbacktrace": for args in allArgs: run args, "tests/testall" + +task test_profiler, "test with profiler instrumentation": + var allArgs = @[ + "-d:release -d:chronosProfiling", + ] + + for args in allArgs: + run args, "tests/testall" diff --git a/chronos/asyncfutures2.nim b/chronos/asyncfutures2.nim index 33cac70..7beb7ba 100644 --- a/chronos/asyncfutures2.nim +++ b/chronos/asyncfutures2.nim @@ -132,7 +132,7 @@ proc finish(fut: FutureBase, state: FutureState) = # 1. `finish()` is a private procedure and `state` is under our control. # 2. `fut.state` is checked by `checkFinished()`. fut.internalState = state - when chronosFuturesInstrumentation: + when chronosProfiling: if not isNil(onFutureEvent): onFutureEvent(fut, state) when chronosStrictFutureAccess: @@ -316,7 +316,7 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = var next: FutureBase template iterate = while true: - when chronosFuturesInstrumentation: + when chronosProfiling: if not isNil(onFutureExecEvent): onFutureExecEvent(fut, Running) @@ -328,7 +328,7 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = break # If we got thus far, means the future is paused. - when chronosFuturesInstrumentation: + when chronosProfiling: if not isNil(onFutureExecEvent): onFutureExecEvent(fut, Paused) diff --git a/chronos/config.nim b/chronos/config.nim index 3d3dd4d..c3e8a85 100644 --- a/chronos/config.nim +++ b/chronos/config.nim @@ -49,7 +49,7 @@ when (NimMajor, NimMinor) >= (1, 4): ## using `AsyncProcessOption.EvalCommand` and API calls such as ## ``execCommand(command)`` and ``execCommandEx(command)``. - chronosFuturesInstrumentation* {.booldefine.} = defined(chronosFuturesInstrumentation) + chronosProfiling* {.booldefine.} = defined(chronosProfiling) ## Enable instrumentation callbacks which are called at ## the start, pause, or end of a Future's lifetime. ## Useful for implementing metrics or other instrumentation. @@ -66,7 +66,7 @@ else: chronosFutureTracking*: bool = defined(chronosDebug) or defined(chronosFutureTracking) chronosDumpAsync*: bool = defined(nimDumpAsync) - chronosFuturesInstrumentation*: bool = defined(chronosFuturesInstrumentation) + chronosProfiling*: bool = defined(chronosProfiling) chronosProcShell* {.strdefine.}: string = when defined(windows): "cmd.exe" diff --git a/chronos/futures.nim b/chronos/futures.nim index c93e64c..3f5f092 100644 --- a/chronos/futures.nim +++ b/chronos/futures.nim @@ -93,7 +93,7 @@ when chronosFutureTracking: var futureList* {.threadvar.}: FutureList -when chronosFuturesInstrumentation: +when chronosProfiling: type FutureExecutionState* {.pure.} = enum Running, Paused @@ -128,7 +128,7 @@ proc internalInitFutureBase*( futureList.head = fut futureList.count.inc() - when chronosFuturesInstrumentation: + when chronosProfiling: if not isNil(onFutureEvent): onFutureEvent(fut, state) diff --git a/chronos/profiler.nim b/chronos/profiler.nim new file mode 100644 index 0000000..25bf70f --- /dev/null +++ b/chronos/profiler.nim @@ -0,0 +1,28 @@ +import ./config + +when chronosProfiling: + import futures + import ./profiler/[events, metrics] + + export futures, events, metrics + + when not defined(chronosFutureId): + {.error "chronosProfiling requires chronosFutureId to be enabled".} + + var futureMetrics {.threadvar.}: ProfilerMetrics + + proc getMetrics*(): ProfilerMetrics = + ## Returns metrics for the current event loop. + result = futureMetrics + + proc enableEventCallbacks*(): void = + onFutureEvent = handleFutureEventCB + onFutureExecEvent = handleFutureExecEventCB + + proc enable*() = + ## Enables profiling on the current event loop. + if not isNil(handleFutureEvent): return + + enableEventCallbacks() + handleFutureEvent = proc (e: Event) {.nimcall.} = + futureMetrics.processEvent(e) diff --git a/chronos/profiler/events.nim b/chronos/profiler/events.nim index 43bcc01..c9e7346 100644 --- a/chronos/profiler/events.nim +++ b/chronos/profiler/events.nim @@ -1,3 +1,8 @@ +## This module defines the lower-level callback implementations that hook into +## the Chronos scheduler when profiling is enabled. The main goal is to provide +## timestamped events changes for futures while allowing a simpler implementation +## (only one event object type) for the remainder of the profiler. + import ".."/timer import ".."/futures import ".."/srcloc @@ -31,7 +36,8 @@ proc mkEvent(future: FutureBase, state: ExtendedFutureState): Event = timestamp: Moment.now(), ) -onFutureEvent = proc (future: FutureBase, state: FutureState): void {.nimcall.} = +proc handleFutureEventCB*(future: FutureBase, + state: FutureState): void {.nimcall.} = {.cast(gcsafe).}: let extendedState = case state: of FutureState.Pending: ExtendedFutureState.Pending @@ -42,7 +48,8 @@ onFutureEvent = proc (future: FutureBase, state: FutureState): void {.nimcall.} if not isNil(handleFutureEvent): handleFutureEvent(mkEvent(future, extendedState)) -onFutureExecEvent = proc (future: FutureBase, state: FutureExecutionState): void {.nimcall.} = +proc handleFutureExecEventCB*(future: FutureBase, + state: FutureExecutionState): void {.nimcall.} = {.cast(gcsafe).}: let extendedState = case state: of FutureExecutionState.Running: ExtendedFutureState.Running diff --git a/tests/config.nims b/tests/config.nims index 9a3d66f..5818ac7 100644 --- a/tests/config.nims +++ b/tests/config.nims @@ -9,5 +9,4 @@ switch("threads", "on") switch("define", "nimRawSetjmp") ## REMOVE BEFORE MERGE! ---d:chronosFuturesInstrumentation -# --d:chronosFutureTracking +--d:chronosProfiling diff --git a/tests/profiler/testevents.nim b/tests/profiler/testevents.nim index 0251e07..69caef7 100644 --- a/tests/profiler/testevents.nim +++ b/tests/profiler/testevents.nim @@ -3,7 +3,7 @@ import std/os import unittest2 import ".."/".."/chronos -import ".."/".."/chronos/profiler/[events, metrics] +import ".."/".."/chronos/profiler import ./utils @@ -53,11 +53,16 @@ suite "profiler hooks test suite": test "should emit correct events when a nested child pauses execution": proc child2() {.async.} = + recordSegment("segment 21") await sleepAsync(10.milliseconds) + recordSegment("segment 22") await sleepAsync(10.milliseconds) + recordSegment("segment 23") proc child1() {.async.} = + recordSegment("segment 11") await child2() + recordSegment("segment 12") proc withChildren() {.async.} = recordSegment("segment 1") @@ -73,8 +78,10 @@ suite "profiler hooks test suite": SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"), SimpleEvent(state: ExtendedFutureState.Pending, procedure: "child1"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "child1"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 11"), SimpleEvent(state: ExtendedFutureState.Pending, procedure: "child2"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "child2"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 21"), SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), SimpleEvent(state: ExtendedFutureState.Paused, procedure: "child2"), SimpleEvent(state: ExtendedFutureState.Paused, procedure: "child1"), @@ -83,14 +90,17 @@ suite "profiler hooks test suite": # Second iteration of child2 SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "child2"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 22"), SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), SimpleEvent(state: ExtendedFutureState.Paused, procedure: "child2"), SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "child2"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 23"), SimpleEvent(state: ExtendedFutureState.Completed, procedure: "child2"), # Second iteration child1 SimpleEvent(state: ExtendedFutureState.Running, procedure: "child1"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 12"), SimpleEvent(state: ExtendedFutureState.Completed, procedure: "child1"), # Second iteration of parent diff --git a/tests/profiler/utils.nim b/tests/profiler/utils.nim index 8237632..966a875 100644 --- a/tests/profiler/utils.nim +++ b/tests/profiler/utils.nim @@ -1,8 +1,5 @@ -import std/with - import ".."/".."/chronos -import ".."/".."/chronos/profiler/events -import ".."/".."/chronos/profiler/metrics +import ".."/".."/chronos/profiler type SimpleEvent* = object @@ -26,7 +23,7 @@ proc recordEvent(event: Event) {.nimcall, gcsafe, raises: [].} = SimpleEvent(procedure: $event.location.procedure, state: event.newState)) var timeShifted = event - timeshifted.timestamp = fakeTime + timeShifted.timestamp = fakeTime rawRecording.add(timeShifted) @@ -43,6 +40,9 @@ proc clearRecording*(): void = proc installCallbacks*() = assert not installed, "Callbacks already installed" + + enableEventCallbacks() + oldHandleFutureEvent = handleFutureEvent handleFutureEvent = recordEvent diff --git a/tests/testall.nim b/tests/testall.nim index 4861a85..994c4e2 100644 --- a/tests/testall.nim +++ b/tests/testall.nim @@ -8,7 +8,7 @@ import testmacro, testsync, testsoon, testtime, testfut, testsignal, testaddress, testdatagram, teststream, testserver, testbugs, testnet, testasyncstream, testhttpserver, testshttpserver, testhttpclient, - testproc, testratelimit, testfutures, testthreadsync + testproc, testratelimit, testfutures, testthreadsync, testprofiler # Must be imported last to check for Pending futures import testutils diff --git a/tests/testprofiler.nim b/tests/testprofiler.nim index 2dda14e..e5b1a10 100644 --- a/tests/testprofiler.nim +++ b/tests/testprofiler.nim @@ -1,4 +1,10 @@ -import ./profiler/testevents -import ./profiler/testmetrics +import ../chronos/config +when chronosProfiling: + import ../chronos/profiler + + import ./profiler/testevents + import ./profiler/testmetrics + +{.used.} {.warning[UnusedImport]:off.} diff --git a/tests/testutils.nim b/tests/testutils.nim new file mode 100644 index 0000000..e589037 --- /dev/null +++ b/tests/testutils.nim @@ -0,0 +1,87 @@ +# Chronos Test Suite +# (c) Copyright 2020-Present +# Status Research & Development GmbH +# +# Licensed under either of +# Apache License, version 2.0, (LICENSE-APACHEv2) +# MIT license (LICENSE-MIT) +import unittest2 +import ../chronos, ../chronos/config + +{.used.} + +suite "Asynchronous utilities test suite": + when chronosFutureTracking: + proc getCount(): uint = + # This procedure counts number of Future[T] in double-linked list via list + # iteration. + var res = 0'u + for item in pendingFutures(): + inc(res) + res + + test "Future clean and leaks test": + when chronosFutureTracking: + if pendingFuturesCount(WithoutCompleted) == 0'u: + if pendingFuturesCount(OnlyCompleted) > 0'u: + poll() + check pendingFuturesCount() == 0'u + else: + echo dumpPendingFutures() + check false + else: + skip() + + test "FutureList basics test": + when chronosFutureTracking: + var fut1 = newFuture[void]() + check: + getCount() == 1'u + pendingFuturesCount() == 1'u + var fut2 = newFuture[void]() + check: + getCount() == 2'u + pendingFuturesCount() == 2'u + var fut3 = newFuture[void]() + check: + getCount() == 3'u + pendingFuturesCount() == 3'u + fut1.complete() + poll() + check: + getCount() == 2'u + pendingFuturesCount() == 2'u + fut2.fail(newException(ValueError, "")) + poll() + check: + getCount() == 1'u + pendingFuturesCount() == 1'u + fut3.cancel() + poll() + check: + getCount() == 0'u + pendingFuturesCount() == 0'u + else: + skip() + + test "FutureList async procedure test": + when chronosFutureTracking: + proc simpleProc() {.async.} = + await sleepAsync(10.milliseconds) + + var fut = simpleProc() + check: + getCount() == 2'u + pendingFuturesCount() == 2'u + + waitFor fut + check: + getCount() == 1'u + pendingFuturesCount() == 1'u + + poll() + check: + getCount() == 0'u + pendingFuturesCount() == 0'u + else: + skip()