From f9909c405313ff3cad64ea34d905559bdfda0465 Mon Sep 17 00:00:00 2001 From: Jaremy Creechley Date: Thu, 26 Oct 2023 13:50:03 -0700 Subject: [PATCH 01/30] futures profiling instrumentation --- chronos/asyncfutures2.nim | 6 ++ chronos/asyncmacro2.nim | 10 +++ chronos/config.nim | 6 ++ chronos/futures.nim | 12 +++ tests/config.nims | 4 + tests/testutils.nim | 172 ++++++++++++++++++++++++++++++++++++++ 6 files changed, 210 insertions(+) diff --git a/chronos/asyncfutures2.nim b/chronos/asyncfutures2.nim index d170f0825..34920c018 100644 --- a/chronos/asyncfutures2.nim +++ b/chronos/asyncfutures2.nim @@ -132,6 +132,9 @@ 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: + if not(isNil(onFutureStop)): + onFutureStop(fut) when chronosStrictFutureAccess: doAssert fut.internalCancelcb == nil or state != FutureState.Cancelled fut.internalCancelcb = nil # release cancellation callback memory @@ -212,6 +215,9 @@ proc cancel(future: FutureBase, loc: ptr SrcLoc): bool = if future.finished(): return false + when chronosFuturesInstrumentation: + if not(isNil(onFutureStop)): onFutureStop(future) + if not(isNil(future.internalChild)): # If you hit this assertion, you should have used the `CancelledError` # mechanism and/or use a regular `addCallback` diff --git a/chronos/asyncmacro2.nim b/chronos/asyncmacro2.nim index 45146a300..2e0b56d8a 100644 --- a/chronos/asyncmacro2.nim +++ b/chronos/asyncmacro2.nim @@ -297,6 +297,11 @@ proc asyncSingleProc(prc: NimNode): NimNode {.compileTime.} = template await*[T](f: Future[T]): untyped = when declared(chronosInternalRetFuture): chronosInternalRetFuture.internalChild = f + + when chronosFuturesInstrumentation: + if not(isNil(onFuturePause)): + onFuturePause(chronosInternalRetFuture, f) + # `futureContinue` calls the iterator generated by the `async` # transformation - `yield` gives control back to `futureContinue` which is # responsible for resuming execution once the yielded future is finished @@ -316,6 +321,11 @@ template await*[T](f: Future[T]): untyped = template awaitne*[T](f: Future[T]): Future[T] = when declared(chronosInternalRetFuture): chronosInternalRetFuture.internalChild = f + + when chronosFuturesInstrumentation: + if not(isNil(onFuturePause)): + onFuturePause(chronosInternalRetFuture, f) + yield chronosInternalRetFuture.internalChild if chronosInternalRetFuture.internalMustCancel: raise newCancelledError() diff --git a/chronos/config.nim b/chronos/config.nim index 0a439a12a..3d3dd4d23 100644 --- a/chronos/config.nim +++ b/chronos/config.nim @@ -49,6 +49,11 @@ when (NimMajor, NimMinor) >= (1, 4): ## using `AsyncProcessOption.EvalCommand` and API calls such as ## ``execCommand(command)`` and ``execCommandEx(command)``. + chronosFuturesInstrumentation* {.booldefine.} = defined(chronosFuturesInstrumentation) + ## Enable instrumentation callbacks which are called at + ## the start, pause, or end of a Future's lifetime. + ## Useful for implementing metrics or other instrumentation. + else: # 1.2 doesn't support `booldefine` in `when` properly const @@ -61,6 +66,7 @@ else: chronosFutureTracking*: bool = defined(chronosDebug) or defined(chronosFutureTracking) chronosDumpAsync*: bool = defined(nimDumpAsync) + chronosFuturesInstrumentation*: bool = defined(chronosFuturesInstrumentation) chronosProcShell* {.strdefine.}: string = when defined(windows): "cmd.exe" diff --git a/chronos/futures.nim b/chronos/futures.nim index edfae328b..92a492945 100644 --- a/chronos/futures.nim +++ b/chronos/futures.nim @@ -93,6 +93,13 @@ when chronosFutureTracking: var futureList* {.threadvar.}: FutureList +when chronosFuturesInstrumentation: + var + onFutureCreate* {.threadvar.}: proc (fut: FutureBase) {.gcsafe, raises: [].} + onFutureRunning* {.threadvar.}: proc (fut: FutureBase) {.gcsafe, raises: [].} + onFuturePause* {.threadvar.}: proc (fut, child: FutureBase) {.gcsafe, raises: [].} + onFutureStop* {.threadvar.}: proc (fut: FutureBase) {.gcsafe, raises: [].} + # Internal utilities - these are not part of the stable API proc internalInitFutureBase*( fut: FutureBase, @@ -121,6 +128,11 @@ proc internalInitFutureBase*( futureList.head = fut futureList.count.inc() + when chronosFuturesInstrumentation: + if not(isNil(onFutureCreate)): + onFutureCreate(fut) + + # Public API template init*[T](F: type Future[T], fromProc: static[string] = ""): Future[T] = ## Creates a new pending future. diff --git a/tests/config.nims b/tests/config.nims index e1d01894e..9a3d66ff9 100644 --- a/tests/config.nims +++ b/tests/config.nims @@ -7,3 +7,7 @@ switch("threads", "on") # Should be removed when https://github.com/status-im/nim-chronos/issues/284 # will be implemented. switch("define", "nimRawSetjmp") + +## REMOVE BEFORE MERGE! +--d:chronosFuturesInstrumentation +# --d:chronosFutureTracking diff --git a/tests/testutils.nim b/tests/testutils.nim index e5890372a..e3ee1b8a1 100644 --- a/tests/testutils.nim +++ b/tests/testutils.nim @@ -10,6 +10,10 @@ import ../chronos, ../chronos/config {.used.} +when chronosFuturesInstrumentation: + import std/[tables, os, options, hashes] + import ../chronos/timer + suite "Asynchronous utilities test suite": when chronosFutureTracking: proc getCount(): uint = @@ -85,3 +89,171 @@ suite "Asynchronous utilities test suite": pendingFuturesCount() == 0'u else: skip() + + test "check empty futures instrumentation runs": + + when chronosFuturesInstrumentation: + + proc simpleAsyncChild() {.async.} = + echo "child sleep..." + os.sleep(25) + + proc simpleAsync1() {.async.} = + for i in 0..1: + await sleepAsync(40.milliseconds) + await simpleAsyncChild() + echo "sleep..." + os.sleep(50) + + waitFor(simpleAsync1()) + check true + + + test "Example of using Future hooks to gather metrics": + + when chronosFuturesInstrumentation: + + type + FutureMetric = object + ## Holds average timing information for a given closure + closureLoc*: ptr SrcLoc + created*: Moment + start*: Option[Moment] + duration*: Duration + blocks*: int + initDuration*: Duration + durationChildren*: Duration + + CallbackMetric = object + totalExecTime*: Duration + totalWallTime*: Duration + totalRunTime*: Duration + minSingleTime*: Duration + maxSingleTime*: Duration + count*: int64 + + var + futureDurations: Table[uint, FutureMetric] + callbackDurations: Table[ptr SrcLoc, CallbackMetric] + + proc setFutureCreate(fut: FutureBase) {.raises: [].} = + ## used for setting the duration + let loc = fut.internalLocation[Create] + futureDurations[fut.id] = FutureMetric() + futureDurations.withValue(fut.id, metric): + metric.created = Moment.now() + echo loc, "; future create " + + proc setFutureStart(fut: FutureBase) {.raises: [].} = + ## used for setting the duration + let loc = fut.internalLocation[Create] + assert futureDurations.hasKey(fut.id) + futureDurations.withValue(fut.id, metric): + let ts = Moment.now() + metric.start = some ts + metric.blocks.inc() + echo loc, "; future start: ", metric.initDuration + + proc setFuturePause(fut, child: FutureBase) {.raises: [].} = + ## used for setting the duration + let loc = fut.internalLocation[Create] + let childLoc = if child.isNil: nil else: child.internalLocation[Create] + var durationChildren = ZeroDuration + var initDurationChildren = ZeroDuration + if childLoc != nil: + futureDurations.withValue(child.id, metric): + durationChildren = metric.duration + initDurationChildren = metric.initDuration + assert futureDurations.hasKey(fut.id) + futureDurations.withValue(fut.id, metric): + if metric.start.isSome: + let ts = Moment.now() + metric.duration += ts - metric.start.get() + metric.duration -= initDurationChildren + if metric.blocks == 1: + metric.initDuration = ts - metric.created # tricky, + # the first block of a child iterator also + # runs on the parents clock, so we track our first block + # time so any parents can get it + echo loc, "; child firstBlock time: ", initDurationChildren + + metric.durationChildren += durationChildren + metric.start = none Moment + echo loc, "; future pause ", if childLoc.isNil: "" else: " child: " & $childLoc + + proc setFutureDuration(fut: FutureBase) {.raises: [].} = + ## used for setting the duration + let loc = fut.internalLocation[Create] + # assert "set duration: " & $loc + var fm: FutureMetric + # assert futureDurations.pop(fut.id, fm) + futureDurations.withValue(fut.id, metric): + fm = metric[] + + discard callbackDurations.hasKeyOrPut(loc, CallbackMetric(minSingleTime: InfiniteDuration)) + callbackDurations.withValue(loc, metric): + echo loc, " set duration: ", callbackDurations.hasKey(loc) + metric.totalExecTime += fm.duration + metric.totalWallTime += Moment.now() - fm.created + metric.totalRunTime += metric.totalExecTime + fm.durationChildren + echo loc, " child duration: ", fm.durationChildren + metric.count.inc + metric.minSingleTime = min(metric.minSingleTime, fm.duration) + metric.maxSingleTime = max(metric.maxSingleTime, fm.duration) + # handle overflow + if metric.count == metric.count.typeof.high: + metric.totalExecTime = ZeroDuration + metric.count = 0 + + onFutureCreate = + proc (f: FutureBase) = + f.setFutureCreate() + onFutureRunning = + proc (f: FutureBase) = + f.setFutureStart() + onFuturePause = + proc (f, child: FutureBase) = + f.setFuturePause(child) + onFutureStop = + proc (f: FutureBase) = + f.setFuturePause(nil) + f.setFutureDuration() + + proc simpleAsyncChild() {.async.} = + echo "child sleep..." + os.sleep(25) + + proc simpleAsync1() {.async.} = + for i in 0..1: + await sleepAsync(40.milliseconds) + await simpleAsyncChild() + echo "sleep..." + os.sleep(50) + + waitFor(simpleAsync1()) + + let metrics = callbackDurations + echo "\n=== metrics ===" + echo "execTime:\ttime to execute non-async portions of async proc" + echo "runTime:\texecution time + execution time of children" + echo "wallTime:\twall time elapsed for future's lifetime" + for (k,v) in metrics.pairs(): + let count = v.count + if count > 0: + echo "" + echo "metric: ", $k + echo "count: ", count + echo "avg execTime:\t", v.totalExecTime div count, "\ttotal: ", v.totalExecTime + echo "avg wallTime:\t", v.totalWallTime div count, "\ttotal: ", v.totalWallTime + echo "avg runTime:\t", v.totalRunTime div count, "\ttotal: ", v.totalRunTime + if k.procedure == "simpleAsync1": + check v.totalExecTime >= 150.milliseconds() + check v.totalExecTime <= 180.milliseconds() + + check v.totalRunTime >= 200.milliseconds() + check v.totalRunTime <= 230.milliseconds() + discard + echo "" + + else: + skip() From ac6c22c51ac4466c6f633c56887c3f8a680034a1 Mon Sep 17 00:00:00 2001 From: Jaremy Creechley Date: Thu, 26 Oct 2023 15:23:13 -0700 Subject: [PATCH 02/30] futures profiling instrumentation --- chronos/asyncfutures2.nim | 3 +++ tests/testutils.nim | 1 + 2 files changed, 4 insertions(+) diff --git a/chronos/asyncfutures2.nim b/chronos/asyncfutures2.nim index 34920c018..82ccd443a 100644 --- a/chronos/asyncfutures2.nim +++ b/chronos/asyncfutures2.nim @@ -319,6 +319,9 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = var next: FutureBase template iterate = while true: + when chronosFuturesInstrumentation: + if not(isNil(onFutureRunning)): + onFutureRunning(fut) # Call closure to make progress on `fut` until it reaches `yield` (inside # `await` typically) or completes / fails / is cancelled next = fut.internalClosure(fut) diff --git a/tests/testutils.nim b/tests/testutils.nim index e3ee1b8a1..72800d3d6 100644 --- a/tests/testutils.nim +++ b/tests/testutils.nim @@ -247,6 +247,7 @@ suite "Asynchronous utilities test suite": echo "avg wallTime:\t", v.totalWallTime div count, "\ttotal: ", v.totalWallTime echo "avg runTime:\t", v.totalRunTime div count, "\ttotal: ", v.totalRunTime if k.procedure == "simpleAsync1": + echo "v: ", v check v.totalExecTime >= 150.milliseconds() check v.totalExecTime <= 180.milliseconds() From 0a14f702ee53082d0bf63d9130658449eaa0899f Mon Sep 17 00:00:00 2001 From: Jaremy Creechley Date: Fri, 27 Oct 2023 16:16:23 -0700 Subject: [PATCH 03/30] fix test timing --- tests/testutils.nim | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/testutils.nim b/tests/testutils.nim index 72800d3d6..ad23a3a16 100644 --- a/tests/testutils.nim +++ b/tests/testutils.nim @@ -252,7 +252,7 @@ suite "Asynchronous utilities test suite": check v.totalExecTime <= 180.milliseconds() check v.totalRunTime >= 200.milliseconds() - check v.totalRunTime <= 230.milliseconds() + check v.totalRunTime <= 240.milliseconds() discard echo "" From 74e5ebaf4a3b42640eefff00ebba2a28297c0eb1 Mon Sep 17 00:00:00 2001 From: Jaremy Creechley Date: Tue, 31 Oct 2023 12:37:20 -0700 Subject: [PATCH 04/30] fix onFuturePause using template arg, not future object --- chronos/asyncfutures2.nim | 8 ++++---- chronos/asyncmacro2.nim | 8 ++++---- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/chronos/asyncfutures2.nim b/chronos/asyncfutures2.nim index 82ccd443a..9f6533f01 100644 --- a/chronos/asyncfutures2.nim +++ b/chronos/asyncfutures2.nim @@ -133,8 +133,8 @@ proc finish(fut: FutureBase, state: FutureState) = # 2. `fut.state` is checked by `checkFinished()`. fut.internalState = state when chronosFuturesInstrumentation: - if not(isNil(onFutureStop)): - onFutureStop(fut) + if not(isNil(futures.onFutureStop)): + futures.onFutureStop(fut) when chronosStrictFutureAccess: doAssert fut.internalCancelcb == nil or state != FutureState.Cancelled fut.internalCancelcb = nil # release cancellation callback memory @@ -320,8 +320,8 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = template iterate = while true: when chronosFuturesInstrumentation: - if not(isNil(onFutureRunning)): - onFutureRunning(fut) + if not(isNil(futures.onFutureRunning)): + futures.onFutureRunning(fut) # Call closure to make progress on `fut` until it reaches `yield` (inside # `await` typically) or completes / fails / is cancelled next = fut.internalClosure(fut) diff --git a/chronos/asyncmacro2.nim b/chronos/asyncmacro2.nim index 2e0b56d8a..975d76af7 100644 --- a/chronos/asyncmacro2.nim +++ b/chronos/asyncmacro2.nim @@ -299,8 +299,8 @@ template await*[T](f: Future[T]): untyped = chronosInternalRetFuture.internalChild = f when chronosFuturesInstrumentation: - if not(isNil(onFuturePause)): - onFuturePause(chronosInternalRetFuture, f) + if not(isNil(futures.onFuturePause)): + futures.onFuturePause(chronosInternalRetFuture, chronosInternalRetFuture.internalChild) # `futureContinue` calls the iterator generated by the `async` # transformation - `yield` gives control back to `futureContinue` which is @@ -323,8 +323,8 @@ template awaitne*[T](f: Future[T]): Future[T] = chronosInternalRetFuture.internalChild = f when chronosFuturesInstrumentation: - if not(isNil(onFuturePause)): - onFuturePause(chronosInternalRetFuture, f) + if not(isNil(futures.onFuturePause)): + futures.onFuturePause(chronosInternalRetFuture, chronosInternalRetFuture.internalChild) yield chronosInternalRetFuture.internalChild if chronosInternalRetFuture.internalMustCancel: From bd656ab6dfa61497533ebd2f38a1a5d98bfa40aa Mon Sep 17 00:00:00 2001 From: Jaremy Creechley Date: Tue, 31 Oct 2023 12:38:47 -0700 Subject: [PATCH 05/30] fix onFuturePause using template arg, not future object --- tests/testutils.nim | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/testutils.nim b/tests/testutils.nim index ad23a3a16..4ce5b5297 100644 --- a/tests/testutils.nim +++ b/tests/testutils.nim @@ -248,10 +248,10 @@ suite "Asynchronous utilities test suite": echo "avg runTime:\t", v.totalRunTime div count, "\ttotal: ", v.totalRunTime if k.procedure == "simpleAsync1": echo "v: ", v - check v.totalExecTime >= 150.milliseconds() + check v.totalExecTime >= 100.milliseconds() check v.totalExecTime <= 180.milliseconds() - check v.totalRunTime >= 200.milliseconds() + check v.totalRunTime >= 150.milliseconds() check v.totalRunTime <= 240.milliseconds() discard echo "" From d0ed08c4a395c9ede3883a470275821cdee75a53 Mon Sep 17 00:00:00 2001 From: Jaremy Creechley Date: Wed, 1 Nov 2023 17:05:55 -0700 Subject: [PATCH 06/30] non-procs --- chronos/futures.nim | 8 +- tests/config.nims | 2 +- tests/testutils.nim | 186 ++++++++++++++++++++++---------------------- 3 files changed, 100 insertions(+), 96 deletions(-) diff --git a/chronos/futures.nim b/chronos/futures.nim index 92a492945..e67433a03 100644 --- a/chronos/futures.nim +++ b/chronos/futures.nim @@ -95,10 +95,10 @@ when chronosFutureTracking: when chronosFuturesInstrumentation: var - onFutureCreate* {.threadvar.}: proc (fut: FutureBase) {.gcsafe, raises: [].} - onFutureRunning* {.threadvar.}: proc (fut: FutureBase) {.gcsafe, raises: [].} - onFuturePause* {.threadvar.}: proc (fut, child: FutureBase) {.gcsafe, raises: [].} - onFutureStop* {.threadvar.}: proc (fut: FutureBase) {.gcsafe, raises: [].} + onFutureCreate*: proc (fut: FutureBase) {.gcsafe, nimcall, raises: [].} + onFutureRunning*: proc (fut: FutureBase) {.gcsafe, nimcall, raises: [].} + onFuturePause*: proc (fut, child: FutureBase) {.gcsafe, nimcall, raises: [].} + onFutureStop*: proc (fut: FutureBase) {.gcsafe, nimcall, raises: [].} # Internal utilities - these are not part of the stable API proc internalInitFutureBase*( diff --git a/tests/config.nims b/tests/config.nims index 9a3d66ff9..00648b8d1 100644 --- a/tests/config.nims +++ b/tests/config.nims @@ -9,5 +9,5 @@ switch("threads", "on") switch("define", "nimRawSetjmp") ## REMOVE BEFORE MERGE! ---d:chronosFuturesInstrumentation +# --d:chronosFuturesInstrumentation # --d:chronosFutureTracking diff --git a/tests/testutils.nim b/tests/testutils.nim index 4ce5b5297..c6045f2ea 100644 --- a/tests/testutils.nim +++ b/tests/testutils.nim @@ -14,6 +14,29 @@ when chronosFuturesInstrumentation: import std/[tables, os, options, hashes] import ../chronos/timer +type + FutureMetric = object + ## Holds average timing information for a given closure + closureLoc*: ptr SrcLoc + created*: Moment + start*: Option[Moment] + duration*: Duration + blocks*: int + initDuration*: Duration + durationChildren*: Duration + + CallbackMetric = object + totalExecTime*: Duration + totalWallTime*: Duration + totalRunTime*: Duration + minSingleTime*: Duration + maxSingleTime*: Duration + count*: int64 + +var + futureDurations: Table[uint, FutureMetric] + callbackDurations: Table[ptr SrcLoc, CallbackMetric] + suite "Asynchronous utilities test suite": when chronosFutureTracking: proc getCount(): uint = @@ -113,109 +136,90 @@ suite "Asynchronous utilities test suite": when chronosFuturesInstrumentation: - type - FutureMetric = object - ## Holds average timing information for a given closure - closureLoc*: ptr SrcLoc - created*: Moment - start*: Option[Moment] - duration*: Duration - blocks*: int - initDuration*: Duration - durationChildren*: Duration - - CallbackMetric = object - totalExecTime*: Duration - totalWallTime*: Duration - totalRunTime*: Duration - minSingleTime*: Duration - maxSingleTime*: Duration - count*: int64 - - var - futureDurations: Table[uint, FutureMetric] - callbackDurations: Table[ptr SrcLoc, CallbackMetric] - - proc setFutureCreate(fut: FutureBase) {.raises: [].} = - ## used for setting the duration - let loc = fut.internalLocation[Create] - futureDurations[fut.id] = FutureMetric() - futureDurations.withValue(fut.id, metric): - metric.created = Moment.now() - echo loc, "; future create " - - proc setFutureStart(fut: FutureBase) {.raises: [].} = + proc setFutureCreate(fut: FutureBase) {.nimcall, gcsafe, raises: [].} = ## used for setting the duration - let loc = fut.internalLocation[Create] - assert futureDurations.hasKey(fut.id) - futureDurations.withValue(fut.id, metric): - let ts = Moment.now() - metric.start = some ts - metric.blocks.inc() - echo loc, "; future start: ", metric.initDuration - - proc setFuturePause(fut, child: FutureBase) {.raises: [].} = + {.cast(gcsafe).}: + let loc = fut.internalLocation[Create] + futureDurations[fut.id] = FutureMetric() + futureDurations.withValue(fut.id, metric): + metric.created = Moment.now() + echo loc, "; future create " + + proc setFutureStart(fut: FutureBase) {.nimcall, gcsafe, raises: [].} = ## used for setting the duration - let loc = fut.internalLocation[Create] - let childLoc = if child.isNil: nil else: child.internalLocation[Create] - var durationChildren = ZeroDuration - var initDurationChildren = ZeroDuration - if childLoc != nil: - futureDurations.withValue(child.id, metric): - durationChildren = metric.duration - initDurationChildren = metric.initDuration - assert futureDurations.hasKey(fut.id) - futureDurations.withValue(fut.id, metric): - if metric.start.isSome: + {.cast(gcsafe).}: + let loc = fut.internalLocation[Create] + assert futureDurations.hasKey(fut.id) + futureDurations.withValue(fut.id, metric): let ts = Moment.now() - metric.duration += ts - metric.start.get() - metric.duration -= initDurationChildren - if metric.blocks == 1: - metric.initDuration = ts - metric.created # tricky, - # the first block of a child iterator also - # runs on the parents clock, so we track our first block - # time so any parents can get it - echo loc, "; child firstBlock time: ", initDurationChildren - - metric.durationChildren += durationChildren - metric.start = none Moment - echo loc, "; future pause ", if childLoc.isNil: "" else: " child: " & $childLoc - - proc setFutureDuration(fut: FutureBase) {.raises: [].} = + metric.start = some ts + metric.blocks.inc() + echo loc, "; future start: ", metric.initDuration + + proc setFuturePause(fut, child: FutureBase) {.nimcall, gcsafe, raises: [].} = + ## used for setting the duration + {.cast(gcsafe).}: + let loc = fut.internalLocation[Create] + let childLoc = if child.isNil: nil else: child.internalLocation[Create] + var durationChildren = ZeroDuration + var initDurationChildren = ZeroDuration + if childLoc != nil: + futureDurations.withValue(child.id, metric): + durationChildren = metric.duration + initDurationChildren = metric.initDuration + assert futureDurations.hasKey(fut.id) + futureDurations.withValue(fut.id, metric): + if metric.start.isSome: + let ts = Moment.now() + metric.duration += ts - metric.start.get() + metric.duration -= initDurationChildren + if metric.blocks == 1: + metric.initDuration = ts - metric.created # tricky, + # the first block of a child iterator also + # runs on the parents clock, so we track our first block + # time so any parents can get it + echo loc, "; child firstBlock time: ", initDurationChildren + + metric.durationChildren += durationChildren + metric.start = none Moment + echo loc, "; future pause ", if childLoc.isNil: "" else: " child: " & $childLoc + + proc setFutureDuration(fut: FutureBase) {.nimcall, gcsafe, raises: [].} = ## used for setting the duration - let loc = fut.internalLocation[Create] - # assert "set duration: " & $loc - var fm: FutureMetric - # assert futureDurations.pop(fut.id, fm) - futureDurations.withValue(fut.id, metric): - fm = metric[] - - discard callbackDurations.hasKeyOrPut(loc, CallbackMetric(minSingleTime: InfiniteDuration)) - callbackDurations.withValue(loc, metric): - echo loc, " set duration: ", callbackDurations.hasKey(loc) - metric.totalExecTime += fm.duration - metric.totalWallTime += Moment.now() - fm.created - metric.totalRunTime += metric.totalExecTime + fm.durationChildren - echo loc, " child duration: ", fm.durationChildren - metric.count.inc - metric.minSingleTime = min(metric.minSingleTime, fm.duration) - metric.maxSingleTime = max(metric.maxSingleTime, fm.duration) - # handle overflow - if metric.count == metric.count.typeof.high: - metric.totalExecTime = ZeroDuration - metric.count = 0 + {.cast(gcsafe).}: + let loc = fut.internalLocation[Create] + # assert "set duration: " & $loc + var fm: FutureMetric + # assert futureDurations.pop(fut.id, fm) + futureDurations.withValue(fut.id, metric): + fm = metric[] + + discard callbackDurations.hasKeyOrPut(loc, CallbackMetric(minSingleTime: InfiniteDuration)) + callbackDurations.withValue(loc, metric): + echo loc, " set duration: ", callbackDurations.hasKey(loc) + metric.totalExecTime += fm.duration + metric.totalWallTime += Moment.now() - fm.created + metric.totalRunTime += metric.totalExecTime + fm.durationChildren + echo loc, " child duration: ", fm.durationChildren + metric.count.inc + metric.minSingleTime = min(metric.minSingleTime, fm.duration) + metric.maxSingleTime = max(metric.maxSingleTime, fm.duration) + # handle overflow + if metric.count == metric.count.typeof.high: + metric.totalExecTime = ZeroDuration + metric.count = 0 onFutureCreate = - proc (f: FutureBase) = + proc (f: FutureBase) {.nimcall, gcsafe, raises: [].} = f.setFutureCreate() onFutureRunning = - proc (f: FutureBase) = + proc (f: FutureBase) {.nimcall, gcsafe, raises: [].} = f.setFutureStart() onFuturePause = - proc (f, child: FutureBase) = + proc (f, child: FutureBase) {.nimcall, gcsafe, raises: [].} = f.setFuturePause(child) onFutureStop = - proc (f: FutureBase) = + proc (f: FutureBase) {.nimcall, gcsafe, raises: [].} = f.setFuturePause(nil) f.setFutureDuration() From d4809d5a98fc6cda9ff4ed8a8cda7750ebc5b134 Mon Sep 17 00:00:00 2001 From: gmega Date: Wed, 22 Nov 2023 19:31:42 -0300 Subject: [PATCH 07/30] add harness and initial test --- chronos/asyncfutures2.nim | 19 +- chronos/asyncmacro2.nim | 9 - chronos/futures.nim | 15 +- chronos/profiler/events.nim | 68 +++++++ tests/config.nims | 2 +- tests/profiler/testasyncprofiler.nim | 109 +++++++++++ tests/profiler/utils.nim | 53 ++++++ tests/testutils.nim | 264 --------------------------- 8 files changed, 250 insertions(+), 289 deletions(-) create mode 100644 chronos/profiler/events.nim create mode 100644 tests/profiler/testasyncprofiler.nim create mode 100644 tests/profiler/utils.nim delete mode 100644 tests/testutils.nim diff --git a/chronos/asyncfutures2.nim b/chronos/asyncfutures2.nim index 9f6533f01..f3deae880 100644 --- a/chronos/asyncfutures2.nim +++ b/chronos/asyncfutures2.nim @@ -133,8 +133,8 @@ proc finish(fut: FutureBase, state: FutureState) = # 2. `fut.state` is checked by `checkFinished()`. fut.internalState = state when chronosFuturesInstrumentation: - if not(isNil(futures.onFutureStop)): - futures.onFutureStop(fut) + if not isNil(onFutureEvent): + onFutureEvent(fut, state) when chronosStrictFutureAccess: doAssert fut.internalCancelcb == nil or state != FutureState.Cancelled fut.internalCancelcb = nil # release cancellation callback memory @@ -215,9 +215,6 @@ proc cancel(future: FutureBase, loc: ptr SrcLoc): bool = if future.finished(): return false - when chronosFuturesInstrumentation: - if not(isNil(onFutureStop)): onFutureStop(future) - if not(isNil(future.internalChild)): # If you hit this assertion, you should have used the `CancelledError` # mechanism and/or use a regular `addCallback` @@ -320,14 +317,22 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = template iterate = while true: when chronosFuturesInstrumentation: - if not(isNil(futures.onFutureRunning)): - futures.onFutureRunning(fut) + if not isNil(onFutureExecEvent): + onFutureExecEvent(fut, Running) + # Call closure to make progress on `fut` until it reaches `yield` (inside # `await` typically) or completes / fails / is cancelled next = fut.internalClosure(fut) + if fut.internalClosure.finished(): # Reached the end of the transformed proc break + # If we got thus far it means the future still has work to do, so we + # issue a pause. + when chronosFuturesInstrumentation: + if not isNil(onFutureExecEvent): + onFutureExecEvent(fut, Paused) + if next == nil: raiseAssert "Async procedure (" & ($fut.location[LocationKind.Create]) & ") yielded `nil`, are you await'ing a `nil` Future?" diff --git a/chronos/asyncmacro2.nim b/chronos/asyncmacro2.nim index 975d76af7..64c6f07c5 100644 --- a/chronos/asyncmacro2.nim +++ b/chronos/asyncmacro2.nim @@ -298,10 +298,6 @@ template await*[T](f: Future[T]): untyped = when declared(chronosInternalRetFuture): chronosInternalRetFuture.internalChild = f - when chronosFuturesInstrumentation: - if not(isNil(futures.onFuturePause)): - futures.onFuturePause(chronosInternalRetFuture, chronosInternalRetFuture.internalChild) - # `futureContinue` calls the iterator generated by the `async` # transformation - `yield` gives control back to `futureContinue` which is # responsible for resuming execution once the yielded future is finished @@ -321,11 +317,6 @@ template await*[T](f: Future[T]): untyped = template awaitne*[T](f: Future[T]): Future[T] = when declared(chronosInternalRetFuture): chronosInternalRetFuture.internalChild = f - - when chronosFuturesInstrumentation: - if not(isNil(futures.onFuturePause)): - futures.onFuturePause(chronosInternalRetFuture, chronosInternalRetFuture.internalChild) - yield chronosInternalRetFuture.internalChild if chronosInternalRetFuture.internalMustCancel: raise newCancelledError() diff --git a/chronos/futures.nim b/chronos/futures.nim index e67433a03..c93e64c2b 100644 --- a/chronos/futures.nim +++ b/chronos/futures.nim @@ -94,11 +94,11 @@ when chronosFutureTracking: var futureList* {.threadvar.}: FutureList when chronosFuturesInstrumentation: - var - onFutureCreate*: proc (fut: FutureBase) {.gcsafe, nimcall, raises: [].} - onFutureRunning*: proc (fut: FutureBase) {.gcsafe, nimcall, raises: [].} - onFuturePause*: proc (fut, child: FutureBase) {.gcsafe, nimcall, raises: [].} - onFutureStop*: proc (fut: FutureBase) {.gcsafe, nimcall, raises: [].} + type FutureExecutionState* {.pure.} = enum + Running, Paused + + var onFutureEvent* {.threadvar.}: proc (fut: FutureBase, state: FutureState): void {.nimcall, gcsafe, raises: [].} + var onFutureExecEvent* {.threadvar.}: proc(fut: FutureBase, state: FutureExecutionState): void {.nimcall, gcsafe, raises: [].} # Internal utilities - these are not part of the stable API proc internalInitFutureBase*( @@ -129,9 +129,8 @@ proc internalInitFutureBase*( futureList.count.inc() when chronosFuturesInstrumentation: - if not(isNil(onFutureCreate)): - onFutureCreate(fut) - + if not isNil(onFutureEvent): + onFutureEvent(fut, state) # Public API template init*[T](F: type Future[T], fromProc: static[string] = ""): Future[T] = diff --git a/chronos/profiler/events.nim b/chronos/profiler/events.nim new file mode 100644 index 000000000..a18805be0 --- /dev/null +++ b/chronos/profiler/events.nim @@ -0,0 +1,68 @@ +import ".."/futures +import ".."/srcloc + +type + ExtendedFutureState* {.pure.} = enum + Pending, + Running, + Paused, + Completed, + Cancelled, + Failed, + + Event* = object + futureId*: uint + location*: SrcLoc + newState*: ExtendedFutureState + + RunningFuture = object + event: Event + notNil: bool + +var running* {.threadvar.}: RunningFuture +var handleFutureEvent* {.threadvar.}: proc (event: Event) {.nimcall, gcsafe, raises: [].} + +proc dispatch(future: FutureBase, state: ExtendedFutureState) = + let event = Event( + futureId: future.id, + location: future.internalLocation[LocationKind.Create][], + newState: state + ) + + if state != ExtendedFutureState.Running: + handleFutureEvent(event) + return + + # If we have a running future, then it means this is a child. Emits synthetic + # pause event to keep things consistent with thread occupancy semantics. + if running.notNil: + handleFutureEvent(Event( + futureId: running.event.futureId, + location: running.event.location, + newState: Paused + )) + + running = RunningFuture(event: event, notNil: true) + + handleFutureEvent(event) + +onFutureEvent = proc (future: FutureBase, state: FutureState): void {.nimcall.} = + {.cast(gcsafe).}: + let extendedState = case state: + of FutureState.Pending: ExtendedFutureState.Pending + of FutureState.Completed: ExtendedFutureState.Completed + of FutureState.Cancelled: ExtendedFutureState.Cancelled + of FutureState.Failed: ExtendedFutureState.Failed + + dispatch(future, extendedState) + +onFutureExecEvent = proc (future: FutureBase, state: FutureExecutionState): void {.nimcall.} = + {.cast(gcsafe).}: + let extendedState = case state: + of FutureExecutionState.Running: ExtendedFutureState.Running + of FutureExecutionState.Paused: ExtendedFutureState.Paused + + dispatch(future, extendedState) + + + diff --git a/tests/config.nims b/tests/config.nims index 00648b8d1..9a3d66ff9 100644 --- a/tests/config.nims +++ b/tests/config.nims @@ -9,5 +9,5 @@ switch("threads", "on") switch("define", "nimRawSetjmp") ## REMOVE BEFORE MERGE! -# --d:chronosFuturesInstrumentation +--d:chronosFuturesInstrumentation # --d:chronosFutureTracking diff --git a/tests/profiler/testasyncprofiler.nim b/tests/profiler/testasyncprofiler.nim new file mode 100644 index 000000000..2d1893ece --- /dev/null +++ b/tests/profiler/testasyncprofiler.nim @@ -0,0 +1,109 @@ +import std/os + +import unittest2 + +import ".."/".."/chronos +import ".."/".."/chronos/profiler/events + +import ./utils + +suite "profiler hooks test suite": + + setup: + installCallbacks() + + teardown: + clearRecording() + revertCallbacks() + + test "should emit correct events for a simple future": + + proc simple() {.async.} = + os.sleep(1) + + waitFor simple() + + check getRecording().forProcs("simple") == @[ + SimpleEvent(state: Pending, procedure: "simple"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "simple"), + SimpleEvent(state: Completed, procedure: "simple"), + ] + + # test "should emit correct events for a future with children": + # proc child1() {.async.} = + # os.sleep(1) + + # proc withChildren() {.async.} = + # await child1() + + # waitFor withChildren() + + # check getRecording().forProcs("withChildren", "child1") == @[ + # Event(kind: EventKind.Create, procedure: "withChildren"), + # Event(kind: EventKind.Run, procedure: "withChildren"), + # Event(kind: EventKind.Create, procedure: "child1"), + # Event(kind: EventKind.Pause, procedure: "withChildren"), + # Event(kind: EventKind.Run, procedure: "child1"), + # Event(kind: EventKind.Complete, procedure: "child1"), + # Event(kind: EventKind.Run, procedure: "withChildren"), + # Event(kind: EventKind.Complete, procedure: "withChildren"), + # ] + + # test "should emit correct events for a future with timers": + # proc withChildren() {.async.} = + # await sleepAsync(1.milliseconds) + + # waitFor withChildren() + + # check getRecording().forProcs( + # "withChildren", "chronos.sleepAsync(Duration)") == @[ + # Event(kind: EventKind.Create, procedure: "withChildren"), + # Event(kind: EventKind.Run, procedure: "withChildren"), + # Event(kind: EventKind.Pause, procedure: "withChildren"), + # Event(kind: EventKind.Create, procedure: "chronos.sleepAsync(Duration)"), + # # Timers don't "run" + # Event(kind: EventKind.Complete, procedure: "chronos.sleepAsync(Duration)"), + # Event(kind: EventKind.Run, procedure: "withChildren"), + # Event(kind: EventKind.Complete, procedure: "withChildren"), + # ] + + # test "should emit correct events when futures are canceled": + # proc withCancellation() {.async.} = + # let f = sleepyHead() + # f.cancel() + + # proc sleepyHead() {.async.} = + # await sleepAsync(10.minutes) + + # waitFor withCancellation() + + # check getRecording().forProcs("sleepyHead", "withCancellation") == @[ + # Event(kind: EventKind.Create, procedure: "withCancellation"), + # Event(kind: EventKind.Create, procedure: "sleepyHead"), + # Event(kind: EventKind.Run, procedure: "sleepyHead"), + # ] + +# type +# FakeFuture = object +# id: uint +# internalLocation*: array[LocationKind, ptr SrcLoc] + +# suite "asyncprofiler metrics": + +# test "should not keep metrics for a pending future in memory after it completes": + +# var fakeLoc = SrcLoc(procedure: "foo", file: "foo.nim", line: 1) +# let future = FakeFuture( +# id: 1, +# internalLocation: [ +# LocationKind.Create: addr fakeLoc, +# LocationKind.Finish: addr fakeLoc, +# ]) + +# var profiler = AsyncProfiler[FakeFuture]() + +# profiler.handleFutureCreate(future) +# profiler.handleFutureComplete(future) + +# check len(profiler.getPerFutureMetrics()) == 0 + diff --git a/tests/profiler/utils.nim b/tests/profiler/utils.nim new file mode 100644 index 000000000..b100113d9 --- /dev/null +++ b/tests/profiler/utils.nim @@ -0,0 +1,53 @@ +import std/sequtils +import std/sugar + +import ".."/".."/chronos +import ".."/".."/chronos/profiler/events + +type + SimpleEvent* = object + procedure*: string + state*: ExtendedFutureState + +# XXX this is sort of bad cause we get global state all over, but the fact we +# can't use closures on callbacks and that callbacks themselves are just +# global vars means we can't really do much better for now. + +var recording: seq[SimpleEvent] + +proc forProcs*(self: seq[SimpleEvent], procs: varargs[string]): seq[SimpleEvent] = + collect: + for e in self: + if e.procedure in procs: + e + +# FIXME bad, this needs to be refactored into a callback interface for the profiler. +var oldHandleFutureEvent: proc(event: Event) {.nimcall, gcsafe, raises: [].} = nil +var installed: bool = false + +proc recordEvent(event: Event) {.nimcall, gcsafe, raises: [].} = + {.cast(gcsafe).}: + recording.add( + SimpleEvent( + procedure: $(event.location.procedure), + state: event.newState + ) + ) + +proc getRecording*(): seq[SimpleEvent] = {.cast(gcsafe).}: recording + +proc clearRecording*(): void = recording = @[] + +proc installCallbacks*() = + assert not installed, "Callbacks already installed" + oldHandleFutureEvent = handleFutureEvent + handleFutureEvent = recordEvent + + installed = true + +proc revertCallbacks*() = + assert installed, "Callbacks already uninstalled" + + handleFutureEvent = oldHandleFutureEvent + installed = false + diff --git a/tests/testutils.nim b/tests/testutils.nim deleted file mode 100644 index c6045f2ea..000000000 --- a/tests/testutils.nim +++ /dev/null @@ -1,264 +0,0 @@ -# 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.} - -when chronosFuturesInstrumentation: - import std/[tables, os, options, hashes] - import ../chronos/timer - -type - FutureMetric = object - ## Holds average timing information for a given closure - closureLoc*: ptr SrcLoc - created*: Moment - start*: Option[Moment] - duration*: Duration - blocks*: int - initDuration*: Duration - durationChildren*: Duration - - CallbackMetric = object - totalExecTime*: Duration - totalWallTime*: Duration - totalRunTime*: Duration - minSingleTime*: Duration - maxSingleTime*: Duration - count*: int64 - -var - futureDurations: Table[uint, FutureMetric] - callbackDurations: Table[ptr SrcLoc, CallbackMetric] - -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() - - test "check empty futures instrumentation runs": - - when chronosFuturesInstrumentation: - - proc simpleAsyncChild() {.async.} = - echo "child sleep..." - os.sleep(25) - - proc simpleAsync1() {.async.} = - for i in 0..1: - await sleepAsync(40.milliseconds) - await simpleAsyncChild() - echo "sleep..." - os.sleep(50) - - waitFor(simpleAsync1()) - check true - - - test "Example of using Future hooks to gather metrics": - - when chronosFuturesInstrumentation: - - proc setFutureCreate(fut: FutureBase) {.nimcall, gcsafe, raises: [].} = - ## used for setting the duration - {.cast(gcsafe).}: - let loc = fut.internalLocation[Create] - futureDurations[fut.id] = FutureMetric() - futureDurations.withValue(fut.id, metric): - metric.created = Moment.now() - echo loc, "; future create " - - proc setFutureStart(fut: FutureBase) {.nimcall, gcsafe, raises: [].} = - ## used for setting the duration - {.cast(gcsafe).}: - let loc = fut.internalLocation[Create] - assert futureDurations.hasKey(fut.id) - futureDurations.withValue(fut.id, metric): - let ts = Moment.now() - metric.start = some ts - metric.blocks.inc() - echo loc, "; future start: ", metric.initDuration - - proc setFuturePause(fut, child: FutureBase) {.nimcall, gcsafe, raises: [].} = - ## used for setting the duration - {.cast(gcsafe).}: - let loc = fut.internalLocation[Create] - let childLoc = if child.isNil: nil else: child.internalLocation[Create] - var durationChildren = ZeroDuration - var initDurationChildren = ZeroDuration - if childLoc != nil: - futureDurations.withValue(child.id, metric): - durationChildren = metric.duration - initDurationChildren = metric.initDuration - assert futureDurations.hasKey(fut.id) - futureDurations.withValue(fut.id, metric): - if metric.start.isSome: - let ts = Moment.now() - metric.duration += ts - metric.start.get() - metric.duration -= initDurationChildren - if metric.blocks == 1: - metric.initDuration = ts - metric.created # tricky, - # the first block of a child iterator also - # runs on the parents clock, so we track our first block - # time so any parents can get it - echo loc, "; child firstBlock time: ", initDurationChildren - - metric.durationChildren += durationChildren - metric.start = none Moment - echo loc, "; future pause ", if childLoc.isNil: "" else: " child: " & $childLoc - - proc setFutureDuration(fut: FutureBase) {.nimcall, gcsafe, raises: [].} = - ## used for setting the duration - {.cast(gcsafe).}: - let loc = fut.internalLocation[Create] - # assert "set duration: " & $loc - var fm: FutureMetric - # assert futureDurations.pop(fut.id, fm) - futureDurations.withValue(fut.id, metric): - fm = metric[] - - discard callbackDurations.hasKeyOrPut(loc, CallbackMetric(minSingleTime: InfiniteDuration)) - callbackDurations.withValue(loc, metric): - echo loc, " set duration: ", callbackDurations.hasKey(loc) - metric.totalExecTime += fm.duration - metric.totalWallTime += Moment.now() - fm.created - metric.totalRunTime += metric.totalExecTime + fm.durationChildren - echo loc, " child duration: ", fm.durationChildren - metric.count.inc - metric.minSingleTime = min(metric.minSingleTime, fm.duration) - metric.maxSingleTime = max(metric.maxSingleTime, fm.duration) - # handle overflow - if metric.count == metric.count.typeof.high: - metric.totalExecTime = ZeroDuration - metric.count = 0 - - onFutureCreate = - proc (f: FutureBase) {.nimcall, gcsafe, raises: [].} = - f.setFutureCreate() - onFutureRunning = - proc (f: FutureBase) {.nimcall, gcsafe, raises: [].} = - f.setFutureStart() - onFuturePause = - proc (f, child: FutureBase) {.nimcall, gcsafe, raises: [].} = - f.setFuturePause(child) - onFutureStop = - proc (f: FutureBase) {.nimcall, gcsafe, raises: [].} = - f.setFuturePause(nil) - f.setFutureDuration() - - proc simpleAsyncChild() {.async.} = - echo "child sleep..." - os.sleep(25) - - proc simpleAsync1() {.async.} = - for i in 0..1: - await sleepAsync(40.milliseconds) - await simpleAsyncChild() - echo "sleep..." - os.sleep(50) - - waitFor(simpleAsync1()) - - let metrics = callbackDurations - echo "\n=== metrics ===" - echo "execTime:\ttime to execute non-async portions of async proc" - echo "runTime:\texecution time + execution time of children" - echo "wallTime:\twall time elapsed for future's lifetime" - for (k,v) in metrics.pairs(): - let count = v.count - if count > 0: - echo "" - echo "metric: ", $k - echo "count: ", count - echo "avg execTime:\t", v.totalExecTime div count, "\ttotal: ", v.totalExecTime - echo "avg wallTime:\t", v.totalWallTime div count, "\ttotal: ", v.totalWallTime - echo "avg runTime:\t", v.totalRunTime div count, "\ttotal: ", v.totalRunTime - if k.procedure == "simpleAsync1": - echo "v: ", v - check v.totalExecTime >= 100.milliseconds() - check v.totalExecTime <= 180.milliseconds() - - check v.totalRunTime >= 150.milliseconds() - check v.totalRunTime <= 240.milliseconds() - discard - echo "" - - else: - skip() From 8b5c6a4674fa4c48ad12cdba7981453a9552c0ed Mon Sep 17 00:00:00 2001 From: gmega Date: Fri, 24 Nov 2023 15:19:01 -0300 Subject: [PATCH 08/30] add harness for simulating profiled time and basic profiler metric test --- chronos/asyncfutures2.nim | 5 +- chronos/profiler/events.nim | 39 ++---- chronos/profiler/metrics.nim | 89 ++++++++++++ tests/profiler/example.nim | 18 +++ tests/profiler/testasyncprofiler.nim | 196 +++++++++++++++++---------- tests/profiler/utils.nim | 46 ++++--- 6 files changed, 274 insertions(+), 119 deletions(-) create mode 100644 chronos/profiler/metrics.nim create mode 100644 tests/profiler/example.nim diff --git a/chronos/asyncfutures2.nim b/chronos/asyncfutures2.nim index f3deae880..33cac7015 100644 --- a/chronos/asyncfutures2.nim +++ b/chronos/asyncfutures2.nim @@ -326,9 +326,8 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = if fut.internalClosure.finished(): # Reached the end of the transformed proc break - - # If we got thus far it means the future still has work to do, so we - # issue a pause. + + # If we got thus far, means the future is paused. when chronosFuturesInstrumentation: if not isNil(onFutureExecEvent): onFutureExecEvent(fut, Paused) diff --git a/chronos/profiler/events.nim b/chronos/profiler/events.nim index a18805be0..955401c7c 100644 --- a/chronos/profiler/events.nim +++ b/chronos/profiler/events.nim @@ -1,3 +1,4 @@ +import ".."/timer import ".."/futures import ".."/srcloc @@ -14,38 +15,18 @@ type futureId*: uint location*: SrcLoc newState*: ExtendedFutureState + timestamp*: Moment - RunningFuture = object - event: Event - notNil: bool - -var running* {.threadvar.}: RunningFuture var handleFutureEvent* {.threadvar.}: proc (event: Event) {.nimcall, gcsafe, raises: [].} -proc dispatch(future: FutureBase, state: ExtendedFutureState) = - let event = Event( +proc mkEvent(future: FutureBase, state: ExtendedFutureState): Event = + Event( futureId: future.id, - location: future.internalLocation[LocationKind.Create][], - newState: state + location: future.internalLocation[Create][], + newState: state, + timestamp: Moment.now(), ) - - if state != ExtendedFutureState.Running: - handleFutureEvent(event) - return - - # If we have a running future, then it means this is a child. Emits synthetic - # pause event to keep things consistent with thread occupancy semantics. - if running.notNil: - handleFutureEvent(Event( - futureId: running.event.futureId, - location: running.event.location, - newState: Paused - )) - - running = RunningFuture(event: event, notNil: true) - handleFutureEvent(event) - onFutureEvent = proc (future: FutureBase, state: FutureState): void {.nimcall.} = {.cast(gcsafe).}: let extendedState = case state: @@ -54,7 +35,8 @@ onFutureEvent = proc (future: FutureBase, state: FutureState): void {.nimcall.} of FutureState.Cancelled: ExtendedFutureState.Cancelled of FutureState.Failed: ExtendedFutureState.Failed - dispatch(future, extendedState) + if not isNil(handleFutureEvent): + handleFutureEvent(mkEvent(future, extendedState)) onFutureExecEvent = proc (future: FutureBase, state: FutureExecutionState): void {.nimcall.} = {.cast(gcsafe).}: @@ -62,7 +44,8 @@ onFutureExecEvent = proc (future: FutureBase, state: FutureExecutionState): void of FutureExecutionState.Running: ExtendedFutureState.Running of FutureExecutionState.Paused: ExtendedFutureState.Paused - dispatch(future, extendedState) + if not isNil(handleFutureEvent): + handleFutureEvent(mkEvent(future, extendedState)) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim new file mode 100644 index 000000000..b6adc21cd --- /dev/null +++ b/chronos/profiler/metrics.nim @@ -0,0 +1,89 @@ +import std/tables + +import ./events +import ../[timer, srcloc] + +export timer, tables, srcloc + +type + Clock* = proc (): Moment + + AggregateFutureMetrics* = object + execTime*: Duration + childrenExecTime*: Duration + wallClockTime*: Duration + + RunningFuture* = object + state*: ExtendedFutureState + created*: Moment + lastStarted*: Moment + timeToFirstPause*: Duration + partialExecTime*: Duration + pauses*: uint + + ProfilerMetrics* = object + partials: Table[uint, RunningFuture] + totals*: Table[SrcLoc, AggregateFutureMetrics] + +proc init*(T: typedesc[ProfilerMetrics]): ProfilerMetrics = + result.clock = timer.now + result.partials = initTable[uint, RunningFuture]() + result.totals = initTable[SrcLoc, AggregateFutureMetrics]() + +proc futureCreated(self: var ProfilerMetrics, event: Event): void = + assert not self.partials.hasKey(event.futureId) + + self.partials[event.futureId] = RunningFuture( + created: event.timestamp, + state: Pending, + ) + +proc futureRunning(self: var ProfilerMetrics, event: Event): void = + assert self.partials.hasKey(event.futureId) + + self.partials.withValue(event.futureId, metrics): + assert metrics.state == Pending or metrics.state == Paused + + metrics.lastStarted = event.timestamp + metrics.state = Running + +proc futurePaused(self: var ProfilerMetrics, event: Event): void = + assert self.partials.hasKey(event.futureId) + + self.partials.withValue(event.futureId, metrics): + assert metrics.state == Running + + let segmentExecTime = event.timestamp - metrics.lastStarted + if metrics.pauses == 0: + metrics.timeToFirstPause = segmentExecTime + metrics.partialExecTime += segmentExecTime + metrics.pauses += 1 + metrics.state = Paused + +proc futureCompleted(self: var ProfilerMetrics, event: Event): void = + self.partials.withValue(event.futureId, metrics): + if metrics.state == Running: + self.futurePaused(event) + + let location = event.location + if not self.totals.hasKey(location): + self.totals[location] = AggregateFutureMetrics() + + self.totals.withValue(location, aggMetrics): + aggMetrics.execTime += metrics.partialExecTime + aggMetrics.wallClockTime += event.timestamp - metrics.created + + self.partials.del(event.futureId) + +proc processEvent*(self: var ProfilerMetrics, event: Event): void = + case event.newState: + of Pending: self.futureCreated(event) + of Running: self.futureRunning(event) + of Paused: self.futurePaused(event) + of Completed: self.futureCompleted(event) + else: + assert false, "Unimplemented" + +proc processAllEvents*(self: var ProfilerMetrics, events: seq[Event]): void = + for event in events: + self.processEvent(event) \ No newline at end of file diff --git a/tests/profiler/example.nim b/tests/profiler/example.nim new file mode 100644 index 000000000..6725ee8b3 --- /dev/null +++ b/tests/profiler/example.nim @@ -0,0 +1,18 @@ +import os +import ../../chronos + +proc child11() {.async.} = + echo "I ran" + await sleepAsync(10.milliseconds) + +proc child2() {.async.} = + os.sleep(10) + +proc child1() {.async.} = + await child2() + await child11() + +proc p() {.async.} = + echo "r1" + await child1() + echo "r2" \ No newline at end of file diff --git a/tests/profiler/testasyncprofiler.nim b/tests/profiler/testasyncprofiler.nim index 2d1893ece..080be062b 100644 --- a/tests/profiler/testasyncprofiler.nim +++ b/tests/profiler/testasyncprofiler.nim @@ -3,7 +3,7 @@ import std/os import unittest2 import ".."/".."/chronos -import ".."/".."/chronos/profiler/events +import ".."/".."/chronos/profiler/[events, metrics] import ./utils @@ -23,87 +23,141 @@ suite "profiler hooks test suite": waitFor simple() - check getRecording().forProcs("simple") == @[ + check recording == @[ SimpleEvent(state: Pending, procedure: "simple"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "simple"), SimpleEvent(state: Completed, procedure: "simple"), ] - # test "should emit correct events for a future with children": - # proc child1() {.async.} = - # os.sleep(1) + test "should emit correct events when a single child runs as part of the parent": - # proc withChildren() {.async.} = - # await child1() - - # waitFor withChildren() - - # check getRecording().forProcs("withChildren", "child1") == @[ - # Event(kind: EventKind.Create, procedure: "withChildren"), - # Event(kind: EventKind.Run, procedure: "withChildren"), - # Event(kind: EventKind.Create, procedure: "child1"), - # Event(kind: EventKind.Pause, procedure: "withChildren"), - # Event(kind: EventKind.Run, procedure: "child1"), - # Event(kind: EventKind.Complete, procedure: "child1"), - # Event(kind: EventKind.Run, procedure: "withChildren"), - # Event(kind: EventKind.Complete, procedure: "withChildren"), - # ] - - # test "should emit correct events for a future with timers": - # proc withChildren() {.async.} = - # await sleepAsync(1.milliseconds) - - # waitFor withChildren() - - # check getRecording().forProcs( - # "withChildren", "chronos.sleepAsync(Duration)") == @[ - # Event(kind: EventKind.Create, procedure: "withChildren"), - # Event(kind: EventKind.Run, procedure: "withChildren"), - # Event(kind: EventKind.Pause, procedure: "withChildren"), - # Event(kind: EventKind.Create, procedure: "chronos.sleepAsync(Duration)"), - # # Timers don't "run" - # Event(kind: EventKind.Complete, procedure: "chronos.sleepAsync(Duration)"), - # Event(kind: EventKind.Run, procedure: "withChildren"), - # Event(kind: EventKind.Complete, procedure: "withChildren"), - # ] - - # test "should emit correct events when futures are canceled": - # proc withCancellation() {.async.} = - # let f = sleepyHead() - # f.cancel() - - # proc sleepyHead() {.async.} = - # await sleepAsync(10.minutes) - - # waitFor withCancellation() - - # check getRecording().forProcs("sleepyHead", "withCancellation") == @[ - # Event(kind: EventKind.Create, procedure: "withCancellation"), - # Event(kind: EventKind.Create, procedure: "sleepyHead"), - # Event(kind: EventKind.Run, procedure: "sleepyHead"), - # ] + proc withChildren() {.async.} = + recordSegment("segment 1") + await sleepAsync(10.milliseconds) + recordSegment("segment 2") + + waitFor withChildren() + + + check recording == @[ + SimpleEvent(state: Pending, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"), + SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: Paused, procedure: "withChildren"), + SimpleEvent(state: Completed, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), + SimpleEvent(state: Completed, procedure: "withChildren"), + ] -# type -# FakeFuture = object -# id: uint -# internalLocation*: array[LocationKind, ptr SrcLoc] + test "should emit correct events when a nested child pauses execution": + proc child2() {.async.} = + await sleepAsync(10.milliseconds) + await sleepAsync(10.milliseconds) + + proc child1() {.async.} = + await child2() + + proc withChildren() {.async.} = + recordSegment("segment 1") + await child1() + recordSegment("segment 2") + + waitFor withChildren() + + check recording == @[ + # First iteration of parent and each child + SimpleEvent(state: Pending, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"), + SimpleEvent(state: ExtendedFutureState.Pending, procedure: "child1"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "child1"), + SimpleEvent(state: ExtendedFutureState.Pending, procedure: "child2"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "child2"), + SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: ExtendedFutureState.Paused, procedure: "child2"), + SimpleEvent(state: ExtendedFutureState.Paused, procedure: "child1"), + SimpleEvent(state: ExtendedFutureState.Paused, procedure: "withChildren"), + + # Second iteration of child2 + SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "child2"), + 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.Completed, procedure: "child2"), + + # Second iteration child1 + SimpleEvent(state: ExtendedFutureState.Running, procedure: "child1"), + SimpleEvent(state: ExtendedFutureState.Completed, procedure: "child1"), + + # Second iteration of parent + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), + SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withChildren"), + ] -# suite "asyncprofiler metrics": -# test "should not keep metrics for a pending future in memory after it completes": +suite "profiler metrics test suite": + + setup: + installCallbacks() -# var fakeLoc = SrcLoc(procedure: "foo", file: "foo.nim", line: 1) -# let future = FakeFuture( -# id: 1, -# internalLocation: [ -# LocationKind.Create: addr fakeLoc, -# LocationKind.Finish: addr fakeLoc, -# ]) + teardown: + clearRecording() + revertCallbacks() + resetTime() + + test "should compute correct times for a simple future": -# var profiler = AsyncProfiler[FakeFuture]() + var metrics = ProfilerMetrics() -# profiler.handleFutureCreate(future) -# profiler.handleFutureComplete(future) + proc simple() {.async.} = + advanceTime(50.milliseconds) + + waitFor simple() -# check len(profiler.getPerFutureMetrics()) == 0 + metrics.processAllEvents(rawRecording) + let simpleMetrics = metrics.forProc("simple") + + check simpleMetrics.execTime == 50.milliseconds + check simpleMetrics.wallClockTime == 50.milliseconds + + + # test "should compute correct times when a single child runs as part of the parent": + + # var metrics = ProfilerMetrics() + + # proc child1() {.async.} = + # advanceTime(10.milliseconds) + + # proc withChildren() {.async.} = + # advanceTime(10.milliseconds) + # await child1() + # advanceTime(10.milliseconds) + + # waitFor withChildren() + + # metrics.processAllEvents(rawRecording) + + # let withChildrenMetrics = metrics.forProc("withChildren") + # let child1Metrics = metrics.forProc("child1") + + # check withChildrenMetrics.execTime == 20.milliseconds + # check withChildrenMetrics.childrenExecTime == 10.milliseconds + # check withChildrenMetrics.wallClockTime == 30.milliseconds + + # check child1Metrics.execTime == 10.milliseconds + # check child1Metrics.wallClockTime == 10.milliseconds + +# # test "should emit correct metrics when a single child runs as part of the parent": + +# # proc withChildren() {.async.} = +# # recordSegment("segment 1") +# # await sleepAsync(10.milliseconds) +# # recordSegment("segment 2") + +# # waitFor withChildren() \ No newline at end of file diff --git a/tests/profiler/utils.nim b/tests/profiler/utils.nim index b100113d9..f9763769d 100644 --- a/tests/profiler/utils.nim +++ b/tests/profiler/utils.nim @@ -1,8 +1,8 @@ -import std/sequtils -import std/sugar +import std/with import ".."/".."/chronos import ".."/".."/chronos/profiler/events +import ".."/".."/chronos/profiler/metrics type SimpleEvent* = object @@ -12,14 +12,9 @@ type # XXX this is sort of bad cause we get global state all over, but the fact we # can't use closures on callbacks and that callbacks themselves are just # global vars means we can't really do much better for now. - -var recording: seq[SimpleEvent] - -proc forProcs*(self: seq[SimpleEvent], procs: varargs[string]): seq[SimpleEvent] = - collect: - for e in self: - if e.procedure in procs: - e +var recording*: seq[SimpleEvent] +var rawRecording*: seq[Event] +var fakeTime*: Moment = Moment.now() # FIXME bad, this needs to be refactored into a callback interface for the profiler. var oldHandleFutureEvent: proc(event: Event) {.nimcall, gcsafe, raises: [].} = nil @@ -28,15 +23,22 @@ var installed: bool = false proc recordEvent(event: Event) {.nimcall, gcsafe, raises: [].} = {.cast(gcsafe).}: recording.add( - SimpleEvent( - procedure: $(event.location.procedure), - state: event.newState - ) - ) + SimpleEvent(procedure: $event.location.procedure, state: event.newState)) -proc getRecording*(): seq[SimpleEvent] = {.cast(gcsafe).}: recording + var timeShifted = event + timeshifted.timestamp = fakeTime -proc clearRecording*(): void = recording = @[] + rawRecording.add(timeShifted) + +proc recordSegment*(segment: string) = + {.cast(gcsafe).}: + recording.add(SimpleEvent( + procedure: segment, + state: ExtendedFutureState.Running + )) + +proc clearRecording*(): void = + recording = @[] proc installCallbacks*() = assert not installed, "Callbacks already installed" @@ -51,3 +53,13 @@ proc revertCallbacks*() = handleFutureEvent = oldHandleFutureEvent installed = false +proc forProc*(self: var ProfilerMetrics, procedure: string): AggregateFutureMetrics = + for (key, aggMetrics) in self.totals.mpairs: + if key.procedure == procedure: + return aggMetrics + +proc resetTime*() = + fakeTime = Moment.now() + +proc advanceTime*(duration: Duration) = + fakeTime += duration \ No newline at end of file From 81711f8b11160cbef00b01120315ad5f849af780 Mon Sep 17 00:00:00 2001 From: gmega Date: Fri, 24 Nov 2023 19:32:41 -0300 Subject: [PATCH 09/30] add support for blocking children --- chronos/profiler/events.nim | 12 ++-- chronos/profiler/metrics.nim | 50 +++++++++++--- .../{testasyncprofiler.nim => testevents.nim} | 67 +------------------ tests/profiler/testmetrics.nim | 52 ++++++++++++++ tests/profiler/utils.nim | 1 + tests/testprofiler.nim | 4 ++ 6 files changed, 106 insertions(+), 80 deletions(-) rename tests/profiler/{testasyncprofiler.nim => testevents.nim} (69%) create mode 100644 tests/profiler/testmetrics.nim create mode 100644 tests/testprofiler.nim diff --git a/chronos/profiler/events.nim b/chronos/profiler/events.nim index 955401c7c..43bcc0154 100644 --- a/chronos/profiler/events.nim +++ b/chronos/profiler/events.nim @@ -12,17 +12,21 @@ type Failed, Event* = object - futureId*: uint - location*: SrcLoc + future: FutureBase newState*: ExtendedFutureState timestamp*: Moment var handleFutureEvent* {.threadvar.}: proc (event: Event) {.nimcall, gcsafe, raises: [].} +proc `location`*(self: Event): SrcLoc = + self.future.internalLocation[Create][] + +proc `futureId`*(self: Event): uint = + self.future.id + proc mkEvent(future: FutureBase, state: ExtendedFutureState): Event = Event( - futureId: future.id, - location: future.internalLocation[Create][], + future: future, newState: state, timestamp: Moment.now(), ) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index b6adc21cd..463a4cdf2 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -1,4 +1,5 @@ import std/tables +import std/options import ./events import ../[timer, srcloc] @@ -6,8 +7,6 @@ import ../[timer, srcloc] export timer, tables, srcloc type - Clock* = proc (): Moment - AggregateFutureMetrics* = object execTime*: Duration childrenExecTime*: Duration @@ -19,16 +18,25 @@ type lastStarted*: Moment timeToFirstPause*: Duration partialExecTime*: Duration + partialChildrenExecTime*: Duration + partialChildrenExecOverlap*: Duration + parent*: Option[uint] pauses*: uint - + ProfilerMetrics* = object + running: seq[uint] partials: Table[uint, RunningFuture] totals*: Table[SrcLoc, AggregateFutureMetrics] -proc init*(T: typedesc[ProfilerMetrics]): ProfilerMetrics = - result.clock = timer.now - result.partials = initTable[uint, RunningFuture]() - result.totals = initTable[SrcLoc, AggregateFutureMetrics]() +proc push(self: var seq[uint], value: uint): void = self.add(value) + +proc pop(self: var seq[uint]): uint = + let value = self[^1] + self.setLen(self.len - 1) + value + +proc peek(self: var seq[uint]): Option[uint] = + if self.len == 0: none(uint) else: self[^1].some proc futureCreated(self: var ProfilerMetrics, event: Event): void = assert not self.partials.hasKey(event.futureId) @@ -38,22 +46,36 @@ proc futureCreated(self: var ProfilerMetrics, event: Event): void = state: Pending, ) +proc bindParent(self: var ProfilerMetrics, metrics: ptr RunningFuture): void = + let current = self.running.peek() + if current.isNone: + return + + if metrics.parent.isSome: + assert metrics.parent.get == current.get + metrics.parent = current + proc futureRunning(self: var ProfilerMetrics, event: Event): void = assert self.partials.hasKey(event.futureId) self.partials.withValue(event.futureId, metrics): assert metrics.state == Pending or metrics.state == Paused + self.bindParent(metrics) + self.running.push(event.futureId) + metrics.lastStarted = event.timestamp metrics.state = Running proc futurePaused(self: var ProfilerMetrics, event: Event): void = assert self.partials.hasKey(event.futureId) + assert event.futureId == self.running.pop() self.partials.withValue(event.futureId, metrics): assert metrics.state == Running let segmentExecTime = event.timestamp - metrics.lastStarted + if metrics.pauses == 0: metrics.timeToFirstPause = segmentExecTime metrics.partialExecTime += segmentExecTime @@ -68,12 +90,18 @@ proc futureCompleted(self: var ProfilerMetrics, event: Event): void = let location = event.location if not self.totals.hasKey(location): self.totals[location] = AggregateFutureMetrics() - + self.totals.withValue(location, aggMetrics): - aggMetrics.execTime += metrics.partialExecTime + aggMetrics.execTime += metrics.partialExecTime - metrics.partialChildrenExecOverlap + aggMetrics.childrenExecTime += metrics.partialChildrenExecTime aggMetrics.wallClockTime += event.timestamp - metrics.created - - self.partials.del(event.futureId) + + if metrics.parent.isSome: + self.partials.withValue(metrics.parent.get, parentMetrics): + parentMetrics.partialChildrenExecTime += metrics.partialExecTime + parentMetrics.partialChildrenExecOverlap += metrics.timeToFirstPause + + self.partials.del(event.futureId) proc processEvent*(self: var ProfilerMetrics, event: Event): void = case event.newState: diff --git a/tests/profiler/testasyncprofiler.nim b/tests/profiler/testevents.nim similarity index 69% rename from tests/profiler/testasyncprofiler.nim rename to tests/profiler/testevents.nim index 080be062b..0251e07bc 100644 --- a/tests/profiler/testasyncprofiler.nim +++ b/tests/profiler/testevents.nim @@ -14,7 +14,7 @@ suite "profiler hooks test suite": teardown: clearRecording() - revertCallbacks() + revertCallbacks() test "should emit correct events for a simple future": @@ -97,67 +97,4 @@ suite "profiler hooks test suite": SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withChildren"), - ] - - -suite "profiler metrics test suite": - - setup: - installCallbacks() - - teardown: - clearRecording() - revertCallbacks() - resetTime() - - test "should compute correct times for a simple future": - - var metrics = ProfilerMetrics() - - proc simple() {.async.} = - advanceTime(50.milliseconds) - - waitFor simple() - - metrics.processAllEvents(rawRecording) - - let simpleMetrics = metrics.forProc("simple") - - check simpleMetrics.execTime == 50.milliseconds - check simpleMetrics.wallClockTime == 50.milliseconds - - - # test "should compute correct times when a single child runs as part of the parent": - - # var metrics = ProfilerMetrics() - - # proc child1() {.async.} = - # advanceTime(10.milliseconds) - - # proc withChildren() {.async.} = - # advanceTime(10.milliseconds) - # await child1() - # advanceTime(10.milliseconds) - - # waitFor withChildren() - - # metrics.processAllEvents(rawRecording) - - # let withChildrenMetrics = metrics.forProc("withChildren") - # let child1Metrics = metrics.forProc("child1") - - # check withChildrenMetrics.execTime == 20.milliseconds - # check withChildrenMetrics.childrenExecTime == 10.milliseconds - # check withChildrenMetrics.wallClockTime == 30.milliseconds - - # check child1Metrics.execTime == 10.milliseconds - # check child1Metrics.wallClockTime == 10.milliseconds - -# # test "should emit correct metrics when a single child runs as part of the parent": - -# # proc withChildren() {.async.} = -# # recordSegment("segment 1") -# # await sleepAsync(10.milliseconds) -# # recordSegment("segment 2") - -# # waitFor withChildren() \ No newline at end of file + ] \ No newline at end of file diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim new file mode 100644 index 000000000..1e8037767 --- /dev/null +++ b/tests/profiler/testmetrics.nim @@ -0,0 +1,52 @@ +import unittest2 + +import ".."/".."/chronos +import ".."/".."/chronos/profiler/metrics + +import ./utils + +suite "profiler metrics test suite": + + setup: + installCallbacks() + + teardown: + clearRecording() + revertCallbacks() + resetTime() + + test "should compute correct times for a simple future": + proc simple() {.async.} = + advanceTime(50.milliseconds) + + waitFor simple() + + var metrics = ProfilerMetrics() + metrics.processAllEvents(rawRecording) + let simpleMetrics = metrics.forProc("simple") + + check simpleMetrics.execTime == 50.milliseconds + check simpleMetrics.wallClockTime == 50.milliseconds + + test "should compute correct times for blocking children": + proc child() {.async.} = + advanceTime(10.milliseconds) + + proc parent() {.async.} = + advanceTime(10.milliseconds) + await child() + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = ProfilerMetrics() + metrics.processAllEvents(rawRecording) + let parentMetrics = metrics.forProc("parent") + let childMetrics = metrics.forProc("child") + + check parentMetrics.execTime == 20.milliseconds + check parentMetrics.childrenExecTime == 10.milliseconds + check parentMetrics.wallClockTime == 30.milliseconds + + check childMetrics.execTime == 10.milliseconds + check childMetrics.wallClockTime == 10.milliseconds diff --git a/tests/profiler/utils.nim b/tests/profiler/utils.nim index f9763769d..96e4166cb 100644 --- a/tests/profiler/utils.nim +++ b/tests/profiler/utils.nim @@ -39,6 +39,7 @@ proc recordSegment*(segment: string) = proc clearRecording*(): void = recording = @[] + rawRecording = @[] proc installCallbacks*() = assert not installed, "Callbacks already installed" diff --git a/tests/testprofiler.nim b/tests/testprofiler.nim new file mode 100644 index 000000000..2dda14e60 --- /dev/null +++ b/tests/testprofiler.nim @@ -0,0 +1,4 @@ +import ./profiler/testevents +import ./profiler/testmetrics + +{.warning[UnusedImport]:off.} From ce1e03aa4efd793c62cd5a308456352453bdfe9d Mon Sep 17 00:00:00 2001 From: gmega Date: Mon, 27 Nov 2023 09:49:44 -0300 Subject: [PATCH 10/30] add test for simple non-blocking future --- tests/profiler/testmetrics.nim | 27 +++++++++++++++++++++------ tests/profiler/utils.nim | 20 +++++++++++++++++++- 2 files changed, 40 insertions(+), 7 deletions(-) diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim index 1e8037767..ec12d9eb8 100644 --- a/tests/profiler/testmetrics.nim +++ b/tests/profiler/testmetrics.nim @@ -14,21 +14,37 @@ suite "profiler metrics test suite": clearRecording() revertCallbacks() resetTime() + + proc recordedMetrics(): ProfilerMetrics = + result.processAllEvents(rawRecording) - test "should compute correct times for a simple future": + test "should compute correct times for a simple blocking future": proc simple() {.async.} = advanceTime(50.milliseconds) waitFor simple() - var metrics = ProfilerMetrics() - metrics.processAllEvents(rawRecording) + var metrics = recordedMetrics() let simpleMetrics = metrics.forProc("simple") check simpleMetrics.execTime == 50.milliseconds check simpleMetrics.wallClockTime == 50.milliseconds - test "should compute correct times for blocking children": + test "should compute correct times for a simple non-blocking future": + proc simple {.async.} = + advanceTime(10.milliseconds) + await advanceTimeAsync(50.milliseconds) + advanceTime(10.milliseconds) + + waitFor simple() + + var metrics = recordedMetrics() + let simpleMetrics = metrics.forProc("simple") + + check simpleMetrics.execTime == 20.milliseconds + check simpleMetrics.wallClockTime == 70.milliseconds + + test "should compute correct times whent there is a single blocking child": proc child() {.async.} = advanceTime(10.milliseconds) @@ -39,8 +55,7 @@ suite "profiler metrics test suite": waitFor parent() - var metrics = ProfilerMetrics() - metrics.processAllEvents(rawRecording) + var metrics = recordedMetrics() let parentMetrics = metrics.forProc("parent") let childMetrics = metrics.forProc("child") diff --git a/tests/profiler/utils.nim b/tests/profiler/utils.nim index 96e4166cb..823763278 100644 --- a/tests/profiler/utils.nim +++ b/tests/profiler/utils.nim @@ -63,4 +63,22 @@ proc resetTime*() = fakeTime = Moment.now() proc advanceTime*(duration: Duration) = - fakeTime += duration \ No newline at end of file + fakeTime += duration + +proc advanceTimeAsync*(duration: Duration): Future[void] = + # Simulates a non-blocking operation that takes the provided duration to + # complete. + var retFuture = newFuture[void]("advanceTimeAsync") + var timer: TimerCallback + + proc completion(data: pointer) {.gcsafe.} = + if not(retFuture.finished()): + advanceTime(duration) + retFuture.complete() + + # The actual value for the timer is irrelevant, the important thing is that + # this causes the parent to pause before we advance time. + timer = setTimer(Moment.fromNow(10.milliseconds), + completion, cast[pointer](retFuture)) + + return retFuture From a5fb393ad806601b1cf02ee02c436c3bdf9cecb3 Mon Sep 17 00:00:00 2001 From: gmega Date: Mon, 27 Nov 2023 09:52:41 -0300 Subject: [PATCH 11/30] add test for future with a single non-blocking child --- tests/profiler/testmetrics.nim | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim index ec12d9eb8..a2c3dbc26 100644 --- a/tests/profiler/testmetrics.nim +++ b/tests/profiler/testmetrics.nim @@ -65,3 +65,27 @@ suite "profiler metrics test suite": check childMetrics.execTime == 10.milliseconds check childMetrics.wallClockTime == 10.milliseconds + + test "should compute correct times when there is a single non-blocking child": + proc child() {.async.} = + advanceTime(10.milliseconds) + await advanceTimeAsync(50.milliseconds) + advanceTime(10.milliseconds) + + proc parent() {.async.} = + advanceTime(10.milliseconds) + await child() + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = recordedMetrics() + let parentMetrics = metrics.forProc("parent") + let childMetrics = metrics.forProc("child") + + check parentMetrics.execTime == 20.milliseconds + check parentMetrics.childrenExecTime == 20.milliseconds + check parentMetrics.wallClockTime == 90.milliseconds + + check childMetrics.execTime == 20.milliseconds + check childMetrics.wallClockTime == 70.milliseconds From e65c48c153433d968b47f1c405e458d3449728e8 Mon Sep 17 00:00:00 2001 From: gmega Date: Mon, 27 Nov 2023 10:58:07 -0300 Subject: [PATCH 12/30] add tests for exceptions, cancellation, and multiple pauses --- chronos/profiler/metrics.nim | 5 +- tests/profiler/testmetrics.nim | 118 ++++++++++++++++++++++++++++++++- 2 files changed, 120 insertions(+), 3 deletions(-) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index 463a4cdf2..bf5dca8d1 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -108,9 +108,10 @@ proc processEvent*(self: var ProfilerMetrics, event: Event): void = of Pending: self.futureCreated(event) of Running: self.futureRunning(event) of Paused: self.futurePaused(event) + # Completion, failure and cancellation are currently handled the same way. of Completed: self.futureCompleted(event) - else: - assert false, "Unimplemented" + of Failed: self.futureCompleted(event) + of Cancelled: self.futureCompleted(event) proc processAllEvents*(self: var ProfilerMetrics, events: seq[Event]): void = for event in events: diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim index a2c3dbc26..4ccc8090f 100644 --- a/tests/profiler/testmetrics.nim +++ b/tests/profiler/testmetrics.nim @@ -44,7 +44,23 @@ suite "profiler metrics test suite": check simpleMetrics.execTime == 20.milliseconds check simpleMetrics.wallClockTime == 70.milliseconds - test "should compute correct times whent there is a single blocking child": + test "should compute correct times for a non-blocking future with multiple pauses": + proc simple {.async.} = + advanceTime(10.milliseconds) + await advanceTimeAsync(50.milliseconds) + advanceTime(10.milliseconds) + await advanceTimeAsync(50.milliseconds) + advanceTime(10.milliseconds) + + waitFor simple() + + var metrics = recordedMetrics() + let simpleMetrics = metrics.forProc("simple") + + check simpleMetrics.execTime == 30.milliseconds + check simpleMetrics.wallClockTime == 130.milliseconds + + test "should compute correct times when there is a single blocking child": proc child() {.async.} = advanceTime(10.milliseconds) @@ -65,6 +81,7 @@ suite "profiler metrics test suite": check childMetrics.execTime == 10.milliseconds check childMetrics.wallClockTime == 10.milliseconds + check childMetrics.childrenExecTime == ZeroDuration test "should compute correct times when there is a single non-blocking child": proc child() {.async.} = @@ -89,3 +106,102 @@ suite "profiler metrics test suite": check childMetrics.execTime == 20.milliseconds check childMetrics.wallClockTime == 70.milliseconds + check childMetrics.childrenExecTime == ZeroDuration + + test "should compute correct times when there are multiple blocking and non-blocking children": + proc blockingChild() {.async.} = + advanceTime(10.milliseconds) + + proc nonblockingChild() {.async.} = + advanceTime(10.milliseconds) + await advanceTimeAsync(20.milliseconds) + advanceTime(10.milliseconds) + + proc parent() {.async.} = + advanceTime(10.milliseconds) + await blockingChild() + advanceTime(10.milliseconds) + await nonblockingChild() + advanceTime(10.milliseconds) + await blockingChild() + advanceTime(10.milliseconds) + await nonblockingChild() + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = recordedMetrics() + + let parentMetrics = metrics.forProc("parent") + let blockingChildMetrics = metrics.forProc("blockingChild") + let nonblockingChildMetrics = metrics.forProc("nonblockingChild") + + check parentMetrics.execTime == 50.milliseconds + check parentMetrics.childrenExecTime == 60.milliseconds + check parentMetrics.wallClockTime == 150.milliseconds + + check blockingChildMetrics.execTime == 20.milliseconds + check blockingChildMetrics.wallClockTime == 20.milliseconds + check blockingChildMetrics.childrenExecTime == ZeroDuration + + check nonblockingChildMetrics.execTime == 40.milliseconds + check nonblockingChildMetrics.wallClockTime == 80.milliseconds + check nonblockingChildMetrics.childrenExecTime == ZeroDuration + + test "should compute correct times when a child throws an exception": + proc child() {.async.} = + advanceTime(10.milliseconds) + raise newException(Exception, "child exception") + + proc parent() {.async.} = + advanceTime(10.milliseconds) + try: + await child() + except: + discard + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = recordedMetrics() + let parentMetrics = metrics.forProc("parent") + let childMetrics = metrics.forProc("child") + + check parentMetrics.execTime == 20.milliseconds + check parentMetrics.childrenExecTime == 10.milliseconds + check parentMetrics.wallClockTime == 30.milliseconds + + check childMetrics.execTime == 10.milliseconds + check childMetrics.wallClockTime == 10.milliseconds + check childMetrics.childrenExecTime == ZeroDuration + + test "should compute correct times when a child gets cancelled": + proc child() {.async.} = + advanceTime(10.milliseconds) + await sleepAsync(1.hours) + + proc parent() {.async.} = + advanceTime(10.milliseconds) + # This is sort of subtle: we simulate that parent runs for 10 + # milliseconds before actually cancelling the child. This renders the + # test case less trivial as those 10 milliseconds should be billed as + # wallclock time at the child, causing the child's exec time and its + # wallclock time to differ. + let child = child() + advanceTime(10.milliseconds) + await child.cancelAndWait() + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = recordedMetrics() + let parentMetrics = metrics.forProc("parent") + let childMetrics = metrics.forProc("child") + + check parentMetrics.execTime == 30.milliseconds + check parentMetrics.childrenExecTime == 10.milliseconds + check parentMetrics.wallClockTime == 40.milliseconds + + check childMetrics.execTime == 10.milliseconds + check childMetrics.wallClockTime == 20.milliseconds + check childMetrics.childrenExecTime == ZeroDuration \ No newline at end of file From d320e2ab09998d66c2306c7132dc181e9ee53d95 Mon Sep 17 00:00:00 2001 From: gmega Date: Mon, 27 Nov 2023 12:27:14 -0300 Subject: [PATCH 13/30] 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 6b4ac58a8..fd83e7f01 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 33cac7015..7beb7bae1 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 3d3dd4d23..c3e8a858e 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 c93e64c2b..3f5f092b2 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 000000000..25bf70fce --- /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 43bcc0154..c9e7346e0 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 9a3d66ff9..5818ac78f 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 0251e07bc..69caef74b 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 823763278..966a87592 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 4861a85eb..994c4e2b1 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 2dda14e60..e5b1a107d 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 000000000..e5890372a --- /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() From d80fa15233f1c042c45c3c1a8c053fa9e2ab54b6 Mon Sep 17 00:00:00 2001 From: gmega Date: Mon, 27 Nov 2023 14:11:06 -0300 Subject: [PATCH 14/30] add call count and max exec time; rename enable => enableProfiling to clear up intent --- chronos/profiler.nim | 6 +++--- chronos/profiler/metrics.nim | 8 +++++++- tests/profiler/testmetrics.nim | 37 +++++++++++++++++++++++++++++++++- 3 files changed, 46 insertions(+), 5 deletions(-) diff --git a/chronos/profiler.nim b/chronos/profiler.nim index 25bf70fce..1f43f1104 100644 --- a/chronos/profiler.nim +++ b/chronos/profiler.nim @@ -6,8 +6,8 @@ when chronosProfiling: export futures, events, metrics - when not defined(chronosFutureId): - {.error "chronosProfiling requires chronosFutureId to be enabled".} + when not chronosFutureId: + {.error: "chronosProfiling requires chronosFutureId to be enabled".} var futureMetrics {.threadvar.}: ProfilerMetrics @@ -19,7 +19,7 @@ when chronosProfiling: onFutureEvent = handleFutureEventCB onFutureExecEvent = handleFutureExecEventCB - proc enable*() = + proc enableProfiling*() = ## Enables profiling on the current event loop. if not isNil(handleFutureEvent): return diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index bf5dca8d1..aedb33f0c 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -9,8 +9,10 @@ export timer, tables, srcloc type AggregateFutureMetrics* = object execTime*: Duration + execTimeMax*: Duration childrenExecTime*: Duration wallClockTime*: Duration + callCount*: uint RunningFuture* = object state*: ExtendedFutureState @@ -92,7 +94,11 @@ proc futureCompleted(self: var ProfilerMetrics, event: Event): void = self.totals[location] = AggregateFutureMetrics() self.totals.withValue(location, aggMetrics): - aggMetrics.execTime += metrics.partialExecTime - metrics.partialChildrenExecOverlap + let execTime = metrics.partialExecTime - metrics.partialChildrenExecOverlap + + aggMetrics.callCount.inc() + aggMetrics.execTime += execTime + aggMetrics.execTimeMax = max(aggMetrics.execTimeMax, execTime) aggMetrics.childrenExecTime += metrics.partialChildrenExecTime aggMetrics.wallClockTime += event.timestamp - metrics.created diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim index 4ccc8090f..348914e7e 100644 --- a/tests/profiler/testmetrics.nim +++ b/tests/profiler/testmetrics.nim @@ -204,4 +204,39 @@ suite "profiler metrics test suite": check childMetrics.execTime == 10.milliseconds check childMetrics.wallClockTime == 20.milliseconds - check childMetrics.childrenExecTime == ZeroDuration \ No newline at end of file + check childMetrics.childrenExecTime == ZeroDuration + + test "should compute the correct number of times a proc gets called": + proc child() {.async.} = discard + + proc parent() {.async.} = + for i in 1..10: + await child() + + waitFor parent() + + var metrics = recordedMetrics() + let parentMetrics = metrics.forProc("parent") + let childMetrics = metrics.forProc("child") + + check parentMetrics.callCount == 1 + check childMetrics.callCount == 10 + + test "should compute the maximum execution time for a proc, out of all calls": + var execTimes = @[10.milliseconds, 50.milliseconds, 10.milliseconds] + + proc child(d: Duration) {.async.} = + advanceTime(d) + + proc parent() {.async.} = + for d in execTimes: + await child(d) + + waitFor parent() + + var metrics = recordedMetrics() + let parentMetrics = metrics.forProc("parent") + let childMetrics = metrics.forProc("child") + + check parentMetrics.execTimeMax == ZeroDuration + check childMetrics.execTimeMax == 50.milliseconds \ No newline at end of file From 128531cd830feb1473286654b4d975c5dc36d824 Mon Sep 17 00:00:00 2001 From: gmega Date: Mon, 27 Nov 2023 18:08:08 -0300 Subject: [PATCH 15/30] add accessor to exec time + children, type aliases, minor refactor --- chronos.nimble | 2 +- chronos/profiler/metrics.nim | 15 ++++++++++----- 2 files changed, 11 insertions(+), 6 deletions(-) diff --git a/chronos.nimble b/chronos.nimble index fd83e7f01..a68190c3a 100644 --- a/chronos.nimble +++ b/chronos.nimble @@ -51,7 +51,7 @@ task test_libbacktrace, "test with libbacktrace": task test_profiler, "test with profiler instrumentation": var allArgs = @[ - "-d:release -d:chronosProfiling", + "-d:release -d:chronosFutureId -d:chronosProfiling", ] for args in allArgs: diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index aedb33f0c..38f52765f 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -25,10 +25,15 @@ type parent*: Option[uint] pauses*: uint + MetricsTotals* = Table[SrcLoc, AggregateFutureMetrics] + ProfilerMetrics* = object - running: seq[uint] + callStack: seq[uint] partials: Table[uint, RunningFuture] - totals*: Table[SrcLoc, AggregateFutureMetrics] + totals*: MetricsTotals + +proc `execTimeWithChildren`*(self: AggregateFutureMetrics): Duration = + self.execTime + self.childrenExecTime proc push(self: var seq[uint], value: uint): void = self.add(value) @@ -49,7 +54,7 @@ proc futureCreated(self: var ProfilerMetrics, event: Event): void = ) proc bindParent(self: var ProfilerMetrics, metrics: ptr RunningFuture): void = - let current = self.running.peek() + let current = self.callStack.peek() if current.isNone: return @@ -64,14 +69,14 @@ proc futureRunning(self: var ProfilerMetrics, event: Event): void = assert metrics.state == Pending or metrics.state == Paused self.bindParent(metrics) - self.running.push(event.futureId) + self.callStack.push(event.futureId) metrics.lastStarted = event.timestamp metrics.state = Running proc futurePaused(self: var ProfilerMetrics, event: Event): void = assert self.partials.hasKey(event.futureId) - assert event.futureId == self.running.pop() + assert event.futureId == self.callStack.pop() self.partials.withValue(event.futureId, metrics): assert metrics.state == Running From 1d5d02cfa41e22d3beebff287c89d5b5422147c9 Mon Sep 17 00:00:00 2001 From: gmega Date: Tue, 28 Nov 2023 09:17:58 -0300 Subject: [PATCH 16/30] add location info to assertions to make them easier to trace --- chronos/profiler/metrics.nim | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index 38f52765f..4c22bd13d 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -45,8 +45,11 @@ proc pop(self: var seq[uint]): uint = proc peek(self: var seq[uint]): Option[uint] = if self.len == 0: none(uint) else: self[^1].some +proc `$`(location: SrcLoc): string = + $location.procedure & "[" & $location.file & ":" & $location.line & "]" + proc futureCreated(self: var ProfilerMetrics, event: Event): void = - assert not self.partials.hasKey(event.futureId) + assert not self.partials.hasKey(event.futureId), $event.location self.partials[event.futureId] = RunningFuture( created: event.timestamp, @@ -63,10 +66,11 @@ proc bindParent(self: var ProfilerMetrics, metrics: ptr RunningFuture): void = metrics.parent = current proc futureRunning(self: var ProfilerMetrics, event: Event): void = - assert self.partials.hasKey(event.futureId) + assert self.partials.hasKey(event.futureId), $event.location self.partials.withValue(event.futureId, metrics): - assert metrics.state == Pending or metrics.state == Paused + assert metrics.state == Pending or metrics.state == Paused, + $event.location self.bindParent(metrics) self.callStack.push(event.futureId) @@ -75,11 +79,11 @@ proc futureRunning(self: var ProfilerMetrics, event: Event): void = metrics.state = Running proc futurePaused(self: var ProfilerMetrics, event: Event): void = - assert self.partials.hasKey(event.futureId) - assert event.futureId == self.callStack.pop() + assert self.partials.hasKey(event.futureId), $event.location + assert event.futureId == self.callStack.pop(), $event.location self.partials.withValue(event.futureId, metrics): - assert metrics.state == Running + assert metrics.state == Running, $event.location let segmentExecTime = event.timestamp - metrics.lastStarted From ade1f3018e7913c28fec2e954832d5904d3bbfcb Mon Sep 17 00:00:00 2001 From: gmega Date: Tue, 28 Nov 2023 18:43:22 -0300 Subject: [PATCH 17/30] add failing test case for an async proc with children in its finally block --- tests/profiler/testevents.nim | 26 +++++++++++++++++++++++++- 1 file changed, 25 insertions(+), 1 deletion(-) diff --git a/tests/profiler/testevents.nim b/tests/profiler/testevents.nim index 69caef74b..86c21f77b 100644 --- a/tests/profiler/testevents.nim +++ b/tests/profiler/testevents.nim @@ -107,4 +107,28 @@ suite "profiler hooks test suite": SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withChildren"), - ] \ No newline at end of file + ] + + test "should not say a future is completed before children in finally blocks are run": + skip() + when false: + # TODO: chronos allows completed futures to generate children in their + # finally blocks. This causes a set of transitions that break our state + # machine. + proc withFinally(): Future[void] {.async.} = + try: + return + finally: + await sleepAsync(10.milliseconds) + + waitFor withFinally() + + check recording == @[ + SimpleEvent(state: Pending, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: ExtendedFutureState.Paused, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withFinally") + ] From b64014c154299374f731f0a9cd46d7ca428725f2 Mon Sep 17 00:00:00 2001 From: gmega Date: Wed, 29 Nov 2023 09:52:32 -0300 Subject: [PATCH 18/30] remove example file (included by accident) --- tests/profiler/example.nim | 18 ------------------ 1 file changed, 18 deletions(-) delete mode 100644 tests/profiler/example.nim diff --git a/tests/profiler/example.nim b/tests/profiler/example.nim deleted file mode 100644 index 6725ee8b3..000000000 --- a/tests/profiler/example.nim +++ /dev/null @@ -1,18 +0,0 @@ -import os -import ../../chronos - -proc child11() {.async.} = - echo "I ran" - await sleepAsync(10.milliseconds) - -proc child2() {.async.} = - os.sleep(10) - -proc child1() {.async.} = - await child2() - await child11() - -proc p() {.async.} = - echo "r1" - await child1() - echo "r2" \ No newline at end of file From 9f9b31450e4e86a687b8671b68cdbbfacc259acc Mon Sep 17 00:00:00 2001 From: gmega Date: Wed, 29 Nov 2023 12:18:57 -0300 Subject: [PATCH 19/30] add zombie track test, strenghten zombie event spec test --- chronos/profiler/metrics.nim | 37 +++++++++++++++++++++++++++++----- tests/profiler/testevents.nim | 8 ++++++-- tests/profiler/testmetrics.nim | 19 ++++++++++++++++- 3 files changed, 56 insertions(+), 8 deletions(-) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index 4c22bd13d..58a2cb1fe 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -1,10 +1,11 @@ import std/tables import std/options +import std/sets import ./events import ../[timer, srcloc] -export timer, tables, srcloc +export timer, tables, sets, srcloc type AggregateFutureMetrics* = object @@ -12,6 +13,7 @@ type execTimeMax*: Duration childrenExecTime*: Duration wallClockTime*: Duration + zombieEventCount*: uint callCount*: uint RunningFuture* = object @@ -65,8 +67,29 @@ proc bindParent(self: var ProfilerMetrics, metrics: ptr RunningFuture): void = assert metrics.parent.get == current.get metrics.parent = current -proc futureRunning(self: var ProfilerMetrics, event: Event): void = - assert self.partials.hasKey(event.futureId), $event.location +proc isZombie(self: var ProfilerMetrics, event: Event): bool = + # The first precondition for a zombie future is that it should not have + # an entry in the partial metrics table. + if self.partials.hasKey(event.futureId): + return false + + # The second precondition is that it must have been completed at least once. + # Since we're not tracking IDs for individual completed futures cause that + # would use up a lot of memory, we test if at least one future of this "type" + # (i.e. at the same location) has been completed. If that's not satisfied, + # this positively is a bug. + assert self.totals.hasKey(event.location), $event.location + + self.totals.withValue(event.location, aggMetrics): + # Count zombie events. We can't tell how many events are issued by a single + # zombie future (we think it's one, but who knows) so can't really rely on + # this being a count of the actual zombie futures. + aggMetrics.zombieEventCount.inc() + + true + +proc futureRunning(self: var ProfilerMetrics, event: Event): void = + assert self.partials.hasKey(event.futureId) self.partials.withValue(event.futureId, metrics): assert metrics.state == Pending or metrics.state == Paused, @@ -79,7 +102,9 @@ proc futureRunning(self: var ProfilerMetrics, event: Event): void = metrics.state = Running proc futurePaused(self: var ProfilerMetrics, event: Event): void = - assert self.partials.hasKey(event.futureId), $event.location + # Pause events can come from zombie futures, so we need to check for that. + if self.isZombie(event): return + assert event.futureId == self.callStack.pop(), $event.location self.partials.withValue(event.futureId, metrics): @@ -93,7 +118,9 @@ proc futurePaused(self: var ProfilerMetrics, event: Event): void = metrics.pauses += 1 metrics.state = Paused -proc futureCompleted(self: var ProfilerMetrics, event: Event): void = +proc futureCompleted(self: var ProfilerMetrics, event: Event): void = + assert self.partials.hasKey(event.futureId) + self.partials.withValue(event.futureId, metrics): if metrics.state == Running: self.futurePaused(event) diff --git a/tests/profiler/testevents.nim b/tests/profiler/testevents.nim index 86c21f77b..8d11228c7 100644 --- a/tests/profiler/testevents.nim +++ b/tests/profiler/testevents.nim @@ -38,7 +38,6 @@ suite "profiler hooks test suite": waitFor withChildren() - check recording == @[ SimpleEvent(state: Pending, procedure: "withChildren"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), @@ -119,16 +118,21 @@ suite "profiler hooks test suite": try: return finally: + recordSegment("segment 1") await sleepAsync(10.milliseconds) + # both segments must run + recordSegment("segment 2") waitFor withFinally() check recording == @[ SimpleEvent(state: Pending, procedure: "withFinally"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"), SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), SimpleEvent(state: ExtendedFutureState.Paused, procedure: "withFinally"), SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"), SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), - SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withFinally") + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), + SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withFinally"), ] diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim index 348914e7e..5d692640a 100644 --- a/tests/profiler/testmetrics.nim +++ b/tests/profiler/testmetrics.nim @@ -239,4 +239,21 @@ suite "profiler metrics test suite": let childMetrics = metrics.forProc("child") check parentMetrics.execTimeMax == ZeroDuration - check childMetrics.execTimeMax == 50.milliseconds \ No newline at end of file + check childMetrics.execTimeMax == 50.milliseconds + + test "should count zombie futures and measure their non-zombie execution time": + proc zombie() {.async.} = + try: + advanceTime(10.milliseconds) + return + finally: + advanceTime(10.milliseconds) # this is ran in zombie mode + await advanceTimeAsync(10.milliseconds) + + waitFor zombie() + + var metrics = recordedMetrics() + var zombieMetrics = metrics.forProc("zombie") + + check zombieMetrics.execTime == 10.milliseconds + check zombieMetrics.zombieEventCount == 1 From 9883d7dd8aea76858a06a2c368debb391e11a70b Mon Sep 17 00:00:00 2001 From: gmega Date: Wed, 29 Nov 2023 13:30:15 -0300 Subject: [PATCH 20/30] add zombie checks to run state too --- chronos/profiler/metrics.nim | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index 58a2cb1fe..dac9f2a6b 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -89,7 +89,7 @@ proc isZombie(self: var ProfilerMetrics, event: Event): bool = true proc futureRunning(self: var ProfilerMetrics, event: Event): void = - assert self.partials.hasKey(event.futureId) + if self.isZombie(event): return self.partials.withValue(event.futureId, metrics): assert metrics.state == Pending or metrics.state == Paused, @@ -102,7 +102,6 @@ proc futureRunning(self: var ProfilerMetrics, event: Event): void = metrics.state = Running proc futurePaused(self: var ProfilerMetrics, event: Event): void = - # Pause events can come from zombie futures, so we need to check for that. if self.isZombie(event): return assert event.futureId == self.callStack.pop(), $event.location From 3f774a1fa439a39be97fabb3c731e0725e610c37 Mon Sep 17 00:00:00 2001 From: gmega Date: Fri, 1 Dec 2023 18:41:50 -0300 Subject: [PATCH 21/30] enable future ID; add extra debug info --- chronos/profiler/metrics.nim | 2 +- tests/config.nims | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index dac9f2a6b..f9ea85867 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -118,7 +118,7 @@ proc futurePaused(self: var ProfilerMetrics, event: Event): void = metrics.state = Paused proc futureCompleted(self: var ProfilerMetrics, event: Event): void = - assert self.partials.hasKey(event.futureId) + assert self.partials.hasKey(event.futureId), $event.location self.partials.withValue(event.futureId, metrics): if metrics.state == Running: diff --git a/tests/config.nims b/tests/config.nims index 5818ac78f..b1a6ac2e5 100644 --- a/tests/config.nims +++ b/tests/config.nims @@ -10,3 +10,4 @@ switch("define", "nimRawSetjmp") ## REMOVE BEFORE MERGE! --d:chronosProfiling +--d:chronosFutureId From 5d27b12b176dd3840445cec3c41f97a0a11bbe54 Mon Sep 17 00:00:00 2001 From: gmega Date: Thu, 7 Dec 2023 17:09:45 -0300 Subject: [PATCH 22/30] move instrumentation points for async future FSM into more correct locations --- chronos/asyncfutures2.nim | 17 ++++++++--------- 1 file changed, 8 insertions(+), 9 deletions(-) diff --git a/chronos/asyncfutures2.nim b/chronos/asyncfutures2.nim index 7beb7bae1..0bc4f49ba 100644 --- a/chronos/asyncfutures2.nim +++ b/chronos/asyncfutures2.nim @@ -315,11 +315,11 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = # instead with its original body captured in `fut.closure`. var next: FutureBase template iterate = - while true: - when chronosProfiling: - if not isNil(onFutureExecEvent): - onFutureExecEvent(fut, Running) + when chronosProfiling: + if not isNil(onFutureExecEvent): + onFutureExecEvent(fut, Running) + while true: # Call closure to make progress on `fut` until it reaches `yield` (inside # `await` typically) or completes / fails / is cancelled next = fut.internalClosure(fut) @@ -327,11 +327,6 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = if fut.internalClosure.finished(): # Reached the end of the transformed proc break - # If we got thus far, means the future is paused. - when chronosProfiling: - if not isNil(onFutureExecEvent): - onFutureExecEvent(fut, Paused) - if next == nil: raiseAssert "Async procedure (" & ($fut.location[LocationKind.Create]) & ") yielded `nil`, are you await'ing a `nil` Future?" @@ -342,6 +337,10 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = GC_ref(fut) next.addCallback(CallbackFunc(internalContinue), cast[pointer](fut)) + when chronosProfiling: + if not isNil(onFutureExecEvent): + onFutureExecEvent(fut, Paused) + # return here so that we don't remove the closure below return From 8ffe7f4a8854f98a96ed97b0fd881824d52a28cc Mon Sep 17 00:00:00 2001 From: gmega Date: Thu, 7 Dec 2023 17:10:17 -0300 Subject: [PATCH 23/30] improve assertion error messages --- chronos/profiler/metrics.nim | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index f9ea85867..b7e38db9b 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -93,7 +93,7 @@ proc futureRunning(self: var ProfilerMetrics, event: Event): void = self.partials.withValue(event.futureId, metrics): assert metrics.state == Pending or metrics.state == Paused, - $event.location + $event.location & " " & $metrics.state self.bindParent(metrics) self.callStack.push(event.futureId) @@ -107,7 +107,7 @@ proc futurePaused(self: var ProfilerMetrics, event: Event): void = assert event.futureId == self.callStack.pop(), $event.location self.partials.withValue(event.futureId, metrics): - assert metrics.state == Running, $event.location + assert metrics.state == Running, $event.location & " " & $metrics.state let segmentExecTime = event.timestamp - metrics.lastStarted From 321b6c70246c306ca413c8a9af913eb4da2def56 Mon Sep 17 00:00:00 2001 From: gmega Date: Thu, 7 Dec 2023 17:11:27 -0300 Subject: [PATCH 24/30] capitalize test suite names to make it consistent with the rest --- tests/profiler/testevents.nim | 2 +- tests/profiler/testmetrics.nim | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/profiler/testevents.nim b/tests/profiler/testevents.nim index 8d11228c7..3b9b95756 100644 --- a/tests/profiler/testevents.nim +++ b/tests/profiler/testevents.nim @@ -7,7 +7,7 @@ import ".."/".."/chronos/profiler import ./utils -suite "profiler hooks test suite": +suite "Profiler hooks test suite": setup: installCallbacks() diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim index 5d692640a..5090c9863 100644 --- a/tests/profiler/testmetrics.nim +++ b/tests/profiler/testmetrics.nim @@ -5,7 +5,7 @@ import ".."/".."/chronos/profiler/metrics import ./utils -suite "profiler metrics test suite": +suite "Profiler metrics test suite": setup: installCallbacks() From eb7cf1ae1b3f90736727afc14dc6642c8b2ea9b0 Mon Sep 17 00:00:00 2001 From: gmega Date: Thu, 7 Dec 2023 18:53:12 -0300 Subject: [PATCH 25/30] enable profiling on testprofiler; import/export profiler from chronos's root module --- chronos.nim | 5 +++-- chronos/profiler/metrics.nim | 39 +++++++++++++++++++--------------- tests/profiler/testmetrics.nim | 14 ++++++++++++ tests/testprofiler.nim | 2 ++ 4 files changed, 41 insertions(+), 19 deletions(-) diff --git a/chronos.nim b/chronos.nim index 6801b2894..7388f1612 100644 --- a/chronos.nim +++ b/chronos.nim @@ -6,5 +6,6 @@ # Apache License, version 2.0, (LICENSE-APACHEv2) # MIT license (LICENSE-MIT) import chronos/[asyncloop, asyncsync, handles, transport, timer, - asyncproc, debugutils] -export asyncloop, asyncsync, handles, transport, timer, asyncproc, debugutils + asyncproc, debugutils, profiler] +export asyncloop, asyncsync, handles, transport, timer, asyncproc, debugutils, + profiler \ No newline at end of file diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index b7e38db9b..61736162a 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -14,6 +14,7 @@ type childrenExecTime*: Duration wallClockTime*: Duration zombieEventCount*: uint + stillbornCount*: uint callCount*: uint RunningFuture* = object @@ -118,31 +119,35 @@ proc futurePaused(self: var ProfilerMetrics, event: Event): void = metrics.state = Paused proc futureCompleted(self: var ProfilerMetrics, event: Event): void = - assert self.partials.hasKey(event.futureId), $event.location - - self.partials.withValue(event.futureId, metrics): - if metrics.state == Running: - self.futurePaused(event) - - let location = event.location - if not self.totals.hasKey(location): - self.totals[location] = AggregateFutureMetrics() - - self.totals.withValue(location, aggMetrics): - let execTime = metrics.partialExecTime - metrics.partialChildrenExecOverlap + let location = event.location + if not self.totals.hasKey(location): + self.totals[location] = AggregateFutureMetrics() + + self.totals.withValue(location, aggMetrics): + if not self.partials.hasKey(event.futureId): + # Stillborn futures are those born in a finish state. We count those cause + # they may also be a byproduct of a bug. + aggMetrics.stillbornCount.inc() + return + + self.partials.withValue(event.futureId, metrics): + if metrics.state == Running: + self.futurePaused(event) + let execTime = metrics.partialExecTime - metrics.partialChildrenExecOverlap + aggMetrics.callCount.inc() aggMetrics.execTime += execTime aggMetrics.execTimeMax = max(aggMetrics.execTimeMax, execTime) aggMetrics.childrenExecTime += metrics.partialChildrenExecTime aggMetrics.wallClockTime += event.timestamp - metrics.created - if metrics.parent.isSome: - self.partials.withValue(metrics.parent.get, parentMetrics): - parentMetrics.partialChildrenExecTime += metrics.partialExecTime - parentMetrics.partialChildrenExecOverlap += metrics.timeToFirstPause + if metrics.parent.isSome: + self.partials.withValue(metrics.parent.get, parentMetrics): + parentMetrics.partialChildrenExecTime += metrics.partialExecTime + parentMetrics.partialChildrenExecOverlap += metrics.timeToFirstPause - self.partials.del(event.futureId) + self.partials.del(event.futureId) proc processEvent*(self: var ProfilerMetrics, event: Event): void = case event.newState: diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim index 5090c9863..cc400bb0e 100644 --- a/tests/profiler/testmetrics.nim +++ b/tests/profiler/testmetrics.nim @@ -1,3 +1,5 @@ +import math +import sequtils import unittest2 import ".."/".."/chronos @@ -257,3 +259,15 @@ suite "Profiler metrics test suite": check zombieMetrics.execTime == 10.milliseconds check zombieMetrics.zombieEventCount == 1 + + test "should count futures which start in a completion state": + let completed {.used.} = Future.completed(42) + let failed {.used.} = Future[int].failed((ref ValueError)(msg: "msg")) + + var metrics = recordedMetrics() + + let stillborns = metrics.totals.pairs.toSeq.map( + proc (item: (SrcLoc, AggregateFutureMetrics)): uint = + item[1].stillbornCount).sum + + check stillborns == 2 \ No newline at end of file diff --git a/tests/testprofiler.nim b/tests/testprofiler.nim index e5b1a107d..a7f8ad553 100644 --- a/tests/testprofiler.nim +++ b/tests/testprofiler.nim @@ -6,5 +6,7 @@ when chronosProfiling: import ./profiler/testevents import ./profiler/testmetrics + enableProfiling() + {.used.} {.warning[UnusedImport]:off.} From 7474c5238d5eeb5f19b1eabfbbd366db959861f5 Mon Sep 17 00:00:00 2001 From: gmega Date: Fri, 8 Dec 2023 10:21:08 -0300 Subject: [PATCH 26/30] remove profiler export from main module; disable profiler in tests by default --- chronos.nim | 5 ++--- tests/config.nims | 4 ---- 2 files changed, 2 insertions(+), 7 deletions(-) diff --git a/chronos.nim b/chronos.nim index 7388f1612..a380485c4 100644 --- a/chronos.nim +++ b/chronos.nim @@ -6,6 +6,5 @@ # Apache License, version 2.0, (LICENSE-APACHEv2) # MIT license (LICENSE-MIT) import chronos/[asyncloop, asyncsync, handles, transport, timer, - asyncproc, debugutils, profiler] -export asyncloop, asyncsync, handles, transport, timer, asyncproc, debugutils, - profiler \ No newline at end of file + asyncproc, debugutils] +export asyncloop, asyncsync, handles, transport, timer, asyncproc, debugutils \ No newline at end of file diff --git a/tests/config.nims b/tests/config.nims index b1a6ac2e5..e1d01894e 100644 --- a/tests/config.nims +++ b/tests/config.nims @@ -7,7 +7,3 @@ switch("threads", "on") # Should be removed when https://github.com/status-im/nim-chronos/issues/284 # will be implemented. switch("define", "nimRawSetjmp") - -## REMOVE BEFORE MERGE! ---d:chronosProfiling ---d:chronosFutureId From c960f96be80b06f3a9146fc17299e03ee9f9dc65 Mon Sep 17 00:00:00 2001 From: gmega Date: Fri, 8 Dec 2023 11:33:58 -0300 Subject: [PATCH 27/30] rename states and callbacks to reflect current domain understanding --- chronos/asyncfutures2.nim | 12 ++++++------ chronos/futures.nim | 10 +++++----- chronos/profiler.nim | 4 ++-- chronos/profiler/events.nim | 10 +++++----- 4 files changed, 18 insertions(+), 18 deletions(-) diff --git a/chronos/asyncfutures2.nim b/chronos/asyncfutures2.nim index 0bc4f49ba..447bfc0fc 100644 --- a/chronos/asyncfutures2.nim +++ b/chronos/asyncfutures2.nim @@ -133,8 +133,8 @@ proc finish(fut: FutureBase, state: FutureState) = # 2. `fut.state` is checked by `checkFinished()`. fut.internalState = state when chronosProfiling: - if not isNil(onFutureEvent): - onFutureEvent(fut, state) + if not isNil(onBaseFutureEvent): + onBaseFutureEvent(fut, state) when chronosStrictFutureAccess: doAssert fut.internalCancelcb == nil or state != FutureState.Cancelled fut.internalCancelcb = nil # release cancellation callback memory @@ -316,8 +316,8 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = var next: FutureBase template iterate = when chronosProfiling: - if not isNil(onFutureExecEvent): - onFutureExecEvent(fut, Running) + if not isNil(onAsyncFutureEvent): + onAsyncFutureEvent(fut, Running) while true: # Call closure to make progress on `fut` until it reaches `yield` (inside @@ -338,8 +338,8 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = next.addCallback(CallbackFunc(internalContinue), cast[pointer](fut)) when chronosProfiling: - if not isNil(onFutureExecEvent): - onFutureExecEvent(fut, Paused) + if not isNil(onAsyncFutureEvent): + onAsyncFutureEvent(fut, Paused) # return here so that we don't remove the closure below return diff --git a/chronos/futures.nim b/chronos/futures.nim index 3f5f092b2..c7111db7a 100644 --- a/chronos/futures.nim +++ b/chronos/futures.nim @@ -94,11 +94,11 @@ when chronosFutureTracking: var futureList* {.threadvar.}: FutureList when chronosProfiling: - type FutureExecutionState* {.pure.} = enum + type AsyncFutureState* {.pure.} = enum Running, Paused - var onFutureEvent* {.threadvar.}: proc (fut: FutureBase, state: FutureState): void {.nimcall, gcsafe, raises: [].} - var onFutureExecEvent* {.threadvar.}: proc(fut: FutureBase, state: FutureExecutionState): void {.nimcall, gcsafe, raises: [].} + var onBaseFutureEvent* {.threadvar.}: proc (fut: FutureBase, state: FutureState): void {.nimcall, gcsafe, raises: [].} + var onAsyncFutureEvent* {.threadvar.}: proc(fut: FutureBase, state: AsyncFutureState): void {.nimcall, gcsafe, raises: [].} # Internal utilities - these are not part of the stable API proc internalInitFutureBase*( @@ -129,8 +129,8 @@ proc internalInitFutureBase*( futureList.count.inc() when chronosProfiling: - if not isNil(onFutureEvent): - onFutureEvent(fut, state) + if not isNil(onBaseFutureEvent): + onBaseFutureEvent(fut, state) # Public API template init*[T](F: type Future[T], fromProc: static[string] = ""): Future[T] = diff --git a/chronos/profiler.nim b/chronos/profiler.nim index 1f43f1104..febe34a50 100644 --- a/chronos/profiler.nim +++ b/chronos/profiler.nim @@ -16,8 +16,8 @@ when chronosProfiling: result = futureMetrics proc enableEventCallbacks*(): void = - onFutureEvent = handleFutureEventCB - onFutureExecEvent = handleFutureExecEventCB + onBaseFutureEvent = handleBaseFutureEvent + onAsyncFutureEvent = handleAsyncFutureEvent proc enableProfiling*() = ## Enables profiling on the current event loop. diff --git a/chronos/profiler/events.nim b/chronos/profiler/events.nim index c9e7346e0..f04f7fc99 100644 --- a/chronos/profiler/events.nim +++ b/chronos/profiler/events.nim @@ -36,7 +36,7 @@ proc mkEvent(future: FutureBase, state: ExtendedFutureState): Event = timestamp: Moment.now(), ) -proc handleFutureEventCB*(future: FutureBase, +proc handleBaseFutureEvent*(future: FutureBase, state: FutureState): void {.nimcall.} = {.cast(gcsafe).}: let extendedState = case state: @@ -48,12 +48,12 @@ proc handleFutureEventCB*(future: FutureBase, if not isNil(handleFutureEvent): handleFutureEvent(mkEvent(future, extendedState)) -proc handleFutureExecEventCB*(future: FutureBase, - state: FutureExecutionState): void {.nimcall.} = +proc handleAsyncFutureEvent*(future: FutureBase, + state: AsyncFutureState): void {.nimcall.} = {.cast(gcsafe).}: let extendedState = case state: - of FutureExecutionState.Running: ExtendedFutureState.Running - of FutureExecutionState.Paused: ExtendedFutureState.Paused + of AsyncFutureState.Running: ExtendedFutureState.Running + of AsyncFutureState.Paused: ExtendedFutureState.Paused if not isNil(handleFutureEvent): handleFutureEvent(mkEvent(future, extendedState)) From f007e1b0fd956591c5fae9040a6c0d11c6ec61cb Mon Sep 17 00:00:00 2001 From: gmega Date: Wed, 31 Jan 2024 11:17:33 -0300 Subject: [PATCH 28/30] initial port of profiler to Chronos V4 --- chronos/config.nim | 13 +++++---- chronos/profiler/events.nim | 9 +++---- chronos/profiler/metrics.nim | 27 ++----------------- tests/profiler/testevents.nim | 49 +++++++++++++++------------------- tests/profiler/testmetrics.nim | 20 +++++++------- 5 files changed, 44 insertions(+), 74 deletions(-) diff --git a/chronos/config.nim b/chronos/config.nim index 9c07d2e34..57571b191 100644 --- a/chronos/config.nim +++ b/chronos/config.nim @@ -31,7 +31,12 @@ const chronosStackTrace* {.booldefine.}: bool = defined(chronosDebug) ## Include stack traces in futures for creation and completion points - chronosFutureId* {.booldefine.}: bool = defined(chronosDebug) + 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. + + chronosFutureId* {.booldefine.}: bool = defined(chronosDebug) or chronosProfiling ## Generate a unique `id` for every future - when disabled, the address of ## the future will be used instead @@ -56,11 +61,6 @@ const ## using `AsyncProcessOption.EvalCommand` and API calls such as ## ``execCommand(command)`` and ``execCommandEx(command)``. - 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. - chronosEventsCount* {.intdefine.} = 64 ## Number of OS poll events retrieved by syscall (epoll, kqueue, poll). @@ -89,7 +89,6 @@ when defined(chronosStrictException): # In chronos v3, this setting was used as the opposite of # `chronosHandleException` - the setting is deprecated to encourage # migration to the new mode. ->>>>>>> master when defined(debug) or defined(chronosConfig): import std/macros diff --git a/chronos/profiler/events.nim b/chronos/profiler/events.nim index f04f7fc99..6d363d2a2 100644 --- a/chronos/profiler/events.nim +++ b/chronos/profiler/events.nim @@ -1,11 +1,10 @@ ## 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. +## timestamped state changes for futures, which form the input for the profiler. -import ".."/timer -import ".."/futures -import ".."/srcloc +import ../timer +import ../futures +import ../srcloc type ExtendedFutureState* {.pure.} = enum diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index 61736162a..1c197631d 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -13,7 +13,6 @@ type execTimeMax*: Duration childrenExecTime*: Duration wallClockTime*: Duration - zombieEventCount*: uint stillbornCount*: uint callCount*: uint @@ -68,29 +67,8 @@ proc bindParent(self: var ProfilerMetrics, metrics: ptr RunningFuture): void = assert metrics.parent.get == current.get metrics.parent = current -proc isZombie(self: var ProfilerMetrics, event: Event): bool = - # The first precondition for a zombie future is that it should not have - # an entry in the partial metrics table. - if self.partials.hasKey(event.futureId): - return false - - # The second precondition is that it must have been completed at least once. - # Since we're not tracking IDs for individual completed futures cause that - # would use up a lot of memory, we test if at least one future of this "type" - # (i.e. at the same location) has been completed. If that's not satisfied, - # this positively is a bug. - assert self.totals.hasKey(event.location), $event.location - - self.totals.withValue(event.location, aggMetrics): - # Count zombie events. We can't tell how many events are issued by a single - # zombie future (we think it's one, but who knows) so can't really rely on - # this being a count of the actual zombie futures. - aggMetrics.zombieEventCount.inc() - - true - proc futureRunning(self: var ProfilerMetrics, event: Event): void = - if self.isZombie(event): return + assert self.partials.hasKey(event.futureId), $event.location self.partials.withValue(event.futureId, metrics): assert metrics.state == Pending or metrics.state == Paused, @@ -103,9 +81,8 @@ proc futureRunning(self: var ProfilerMetrics, event: Event): void = metrics.state = Running proc futurePaused(self: var ProfilerMetrics, event: Event): void = - if self.isZombie(event): return - assert event.futureId == self.callStack.pop(), $event.location + assert self.partials.hasKey(event.futureId), $event.location self.partials.withValue(event.futureId, metrics): assert metrics.state == Running, $event.location & " " & $metrics.state diff --git a/tests/profiler/testevents.nim b/tests/profiler/testevents.nim index 3b9b95756..973439f65 100644 --- a/tests/profiler/testevents.nim +++ b/tests/profiler/testevents.nim @@ -109,30 +109,25 @@ suite "Profiler hooks test suite": ] test "should not say a future is completed before children in finally blocks are run": - skip() - when false: - # TODO: chronos allows completed futures to generate children in their - # finally blocks. This causes a set of transitions that break our state - # machine. - proc withFinally(): Future[void] {.async.} = - try: - return - finally: - recordSegment("segment 1") - await sleepAsync(10.milliseconds) - # both segments must run - recordSegment("segment 2") - - waitFor withFinally() - - check recording == @[ - SimpleEvent(state: Pending, procedure: "withFinally"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"), - SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), - SimpleEvent(state: ExtendedFutureState.Paused, procedure: "withFinally"), - SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), - SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withFinally"), - ] + proc withFinally(): Future[void] {.async.} = + try: + return + finally: + recordSegment("segment 1") + await sleepAsync(10.milliseconds) + # both segments must run + recordSegment("segment 2") + + waitFor withFinally() + + check recording == @[ + SimpleEvent(state: Pending, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"), + SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: ExtendedFutureState.Paused, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), + SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withFinally"), + ] \ No newline at end of file diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim index cc400bb0e..81670fbe8 100644 --- a/tests/profiler/testmetrics.nim +++ b/tests/profiler/testmetrics.nim @@ -151,11 +151,11 @@ suite "Profiler metrics test suite": check nonblockingChildMetrics.childrenExecTime == ZeroDuration test "should compute correct times when a child throws an exception": - proc child() {.async.} = + proc child() {.async: (raises: [CatchableError]).} = advanceTime(10.milliseconds) - raise newException(Exception, "child exception") + raise newException(CatchableError, "child exception") - proc parent() {.async.} = + proc parent() {.async: (raises: [CatchableError]).} = advanceTime(10.milliseconds) try: await child() @@ -243,22 +243,22 @@ suite "Profiler metrics test suite": check parentMetrics.execTimeMax == ZeroDuration check childMetrics.execTimeMax == 50.milliseconds - test "should count zombie futures and measure their non-zombie execution time": - proc zombie() {.async.} = + test "should compute the correct execution time within finally blocks": + proc withFinally() {.async.} = try: advanceTime(10.milliseconds) return finally: - advanceTime(10.milliseconds) # this is ran in zombie mode + advanceTime(10.milliseconds) await advanceTimeAsync(10.milliseconds) + advanceTime(10.milliseconds) - waitFor zombie() + waitFor withFinally() var metrics = recordedMetrics() - var zombieMetrics = metrics.forProc("zombie") + var withFinallyMetrics = metrics.forProc("withFinally") - check zombieMetrics.execTime == 10.milliseconds - check zombieMetrics.zombieEventCount == 1 + check withFinallyMetrics.execTime == 30.milliseconds test "should count futures which start in a completion state": let completed {.used.} = Future.completed(42) From c8899eb134ffdd98dae84dfbfd659d44665026b4 Mon Sep 17 00:00:00 2001 From: gmega Date: Fri, 1 Mar 2024 09:39:12 -0300 Subject: [PATCH 29/30] remove profiler from Chronos, keep only instrumentation code --- chronos/profiler.nim | 28 ---- chronos/profiler/events.nim | 61 -------- chronos/profiler/metrics.nim | 141 ----------------- tests/profiler/testevents.nim | 133 ---------------- tests/profiler/testmetrics.nim | 273 --------------------------------- tests/profiler/utils.nim | 84 ---------- tests/testall.nim | 4 +- tests/testprofiler.nim | 12 -- 8 files changed, 2 insertions(+), 734 deletions(-) delete mode 100644 chronos/profiler.nim delete mode 100644 chronos/profiler/events.nim delete mode 100644 chronos/profiler/metrics.nim delete mode 100644 tests/profiler/testevents.nim delete mode 100644 tests/profiler/testmetrics.nim delete mode 100644 tests/profiler/utils.nim delete mode 100644 tests/testprofiler.nim diff --git a/chronos/profiler.nim b/chronos/profiler.nim deleted file mode 100644 index febe34a50..000000000 --- a/chronos/profiler.nim +++ /dev/null @@ -1,28 +0,0 @@ -import ./config - -when chronosProfiling: - import futures - import ./profiler/[events, metrics] - - export futures, events, metrics - - when not 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 = - onBaseFutureEvent = handleBaseFutureEvent - onAsyncFutureEvent = handleAsyncFutureEvent - - proc enableProfiling*() = - ## 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 deleted file mode 100644 index 6d363d2a2..000000000 --- a/chronos/profiler/events.nim +++ /dev/null @@ -1,61 +0,0 @@ -## 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 state changes for futures, which form the input for the profiler. - -import ../timer -import ../futures -import ../srcloc - -type - ExtendedFutureState* {.pure.} = enum - Pending, - Running, - Paused, - Completed, - Cancelled, - Failed, - - Event* = object - future: FutureBase - newState*: ExtendedFutureState - timestamp*: Moment - -var handleFutureEvent* {.threadvar.}: proc (event: Event) {.nimcall, gcsafe, raises: [].} - -proc `location`*(self: Event): SrcLoc = - self.future.internalLocation[Create][] - -proc `futureId`*(self: Event): uint = - self.future.id - -proc mkEvent(future: FutureBase, state: ExtendedFutureState): Event = - Event( - future: future, - newState: state, - timestamp: Moment.now(), - ) - -proc handleBaseFutureEvent*(future: FutureBase, - state: FutureState): void {.nimcall.} = - {.cast(gcsafe).}: - let extendedState = case state: - of FutureState.Pending: ExtendedFutureState.Pending - of FutureState.Completed: ExtendedFutureState.Completed - of FutureState.Cancelled: ExtendedFutureState.Cancelled - of FutureState.Failed: ExtendedFutureState.Failed - - if not isNil(handleFutureEvent): - handleFutureEvent(mkEvent(future, extendedState)) - -proc handleAsyncFutureEvent*(future: FutureBase, - state: AsyncFutureState): void {.nimcall.} = - {.cast(gcsafe).}: - let extendedState = case state: - of AsyncFutureState.Running: ExtendedFutureState.Running - of AsyncFutureState.Paused: ExtendedFutureState.Paused - - if not isNil(handleFutureEvent): - handleFutureEvent(mkEvent(future, extendedState)) - - - diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim deleted file mode 100644 index 1c197631d..000000000 --- a/chronos/profiler/metrics.nim +++ /dev/null @@ -1,141 +0,0 @@ -import std/tables -import std/options -import std/sets - -import ./events -import ../[timer, srcloc] - -export timer, tables, sets, srcloc - -type - AggregateFutureMetrics* = object - execTime*: Duration - execTimeMax*: Duration - childrenExecTime*: Duration - wallClockTime*: Duration - stillbornCount*: uint - callCount*: uint - - RunningFuture* = object - state*: ExtendedFutureState - created*: Moment - lastStarted*: Moment - timeToFirstPause*: Duration - partialExecTime*: Duration - partialChildrenExecTime*: Duration - partialChildrenExecOverlap*: Duration - parent*: Option[uint] - pauses*: uint - - MetricsTotals* = Table[SrcLoc, AggregateFutureMetrics] - - ProfilerMetrics* = object - callStack: seq[uint] - partials: Table[uint, RunningFuture] - totals*: MetricsTotals - -proc `execTimeWithChildren`*(self: AggregateFutureMetrics): Duration = - self.execTime + self.childrenExecTime - -proc push(self: var seq[uint], value: uint): void = self.add(value) - -proc pop(self: var seq[uint]): uint = - let value = self[^1] - self.setLen(self.len - 1) - value - -proc peek(self: var seq[uint]): Option[uint] = - if self.len == 0: none(uint) else: self[^1].some - -proc `$`(location: SrcLoc): string = - $location.procedure & "[" & $location.file & ":" & $location.line & "]" - -proc futureCreated(self: var ProfilerMetrics, event: Event): void = - assert not self.partials.hasKey(event.futureId), $event.location - - self.partials[event.futureId] = RunningFuture( - created: event.timestamp, - state: Pending, - ) - -proc bindParent(self: var ProfilerMetrics, metrics: ptr RunningFuture): void = - let current = self.callStack.peek() - if current.isNone: - return - - if metrics.parent.isSome: - assert metrics.parent.get == current.get - metrics.parent = current - -proc futureRunning(self: var ProfilerMetrics, event: Event): void = - assert self.partials.hasKey(event.futureId), $event.location - - self.partials.withValue(event.futureId, metrics): - assert metrics.state == Pending or metrics.state == Paused, - $event.location & " " & $metrics.state - - self.bindParent(metrics) - self.callStack.push(event.futureId) - - metrics.lastStarted = event.timestamp - metrics.state = Running - -proc futurePaused(self: var ProfilerMetrics, event: Event): void = - assert event.futureId == self.callStack.pop(), $event.location - assert self.partials.hasKey(event.futureId), $event.location - - self.partials.withValue(event.futureId, metrics): - assert metrics.state == Running, $event.location & " " & $metrics.state - - let segmentExecTime = event.timestamp - metrics.lastStarted - - if metrics.pauses == 0: - metrics.timeToFirstPause = segmentExecTime - metrics.partialExecTime += segmentExecTime - metrics.pauses += 1 - metrics.state = Paused - -proc futureCompleted(self: var ProfilerMetrics, event: Event): void = - let location = event.location - if not self.totals.hasKey(location): - self.totals[location] = AggregateFutureMetrics() - - self.totals.withValue(location, aggMetrics): - if not self.partials.hasKey(event.futureId): - # Stillborn futures are those born in a finish state. We count those cause - # they may also be a byproduct of a bug. - aggMetrics.stillbornCount.inc() - return - - self.partials.withValue(event.futureId, metrics): - if metrics.state == Running: - self.futurePaused(event) - - let execTime = metrics.partialExecTime - metrics.partialChildrenExecOverlap - - aggMetrics.callCount.inc() - aggMetrics.execTime += execTime - aggMetrics.execTimeMax = max(aggMetrics.execTimeMax, execTime) - aggMetrics.childrenExecTime += metrics.partialChildrenExecTime - aggMetrics.wallClockTime += event.timestamp - metrics.created - - if metrics.parent.isSome: - self.partials.withValue(metrics.parent.get, parentMetrics): - parentMetrics.partialChildrenExecTime += metrics.partialExecTime - parentMetrics.partialChildrenExecOverlap += metrics.timeToFirstPause - - self.partials.del(event.futureId) - -proc processEvent*(self: var ProfilerMetrics, event: Event): void = - case event.newState: - of Pending: self.futureCreated(event) - of Running: self.futureRunning(event) - of Paused: self.futurePaused(event) - # Completion, failure and cancellation are currently handled the same way. - of Completed: self.futureCompleted(event) - of Failed: self.futureCompleted(event) - of Cancelled: self.futureCompleted(event) - -proc processAllEvents*(self: var ProfilerMetrics, events: seq[Event]): void = - for event in events: - self.processEvent(event) \ No newline at end of file diff --git a/tests/profiler/testevents.nim b/tests/profiler/testevents.nim deleted file mode 100644 index 973439f65..000000000 --- a/tests/profiler/testevents.nim +++ /dev/null @@ -1,133 +0,0 @@ -import std/os - -import unittest2 - -import ".."/".."/chronos -import ".."/".."/chronos/profiler - -import ./utils - -suite "Profiler hooks test suite": - - setup: - installCallbacks() - - teardown: - clearRecording() - revertCallbacks() - - test "should emit correct events for a simple future": - - proc simple() {.async.} = - os.sleep(1) - - waitFor simple() - - check recording == @[ - SimpleEvent(state: Pending, procedure: "simple"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "simple"), - SimpleEvent(state: Completed, procedure: "simple"), - ] - - test "should emit correct events when a single child runs as part of the parent": - - proc withChildren() {.async.} = - recordSegment("segment 1") - await sleepAsync(10.milliseconds) - recordSegment("segment 2") - - waitFor withChildren() - - check recording == @[ - SimpleEvent(state: Pending, procedure: "withChildren"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"), - SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), - SimpleEvent(state: Paused, procedure: "withChildren"), - SimpleEvent(state: Completed, procedure: "chronos.sleepAsync(Duration)"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), - SimpleEvent(state: Completed, procedure: "withChildren"), - ] - - 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") - await child1() - recordSegment("segment 2") - - waitFor withChildren() - - check recording == @[ - # First iteration of parent and each child - SimpleEvent(state: Pending, procedure: "withChildren"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), - 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"), - SimpleEvent(state: ExtendedFutureState.Paused, procedure: "withChildren"), - - # 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 - SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), - SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withChildren"), - ] - - test "should not say a future is completed before children in finally blocks are run": - proc withFinally(): Future[void] {.async.} = - try: - return - finally: - recordSegment("segment 1") - await sleepAsync(10.milliseconds) - # both segments must run - recordSegment("segment 2") - - waitFor withFinally() - - check recording == @[ - SimpleEvent(state: Pending, procedure: "withFinally"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"), - SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), - SimpleEvent(state: ExtendedFutureState.Paused, procedure: "withFinally"), - SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), - SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), - SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withFinally"), - ] \ No newline at end of file diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim deleted file mode 100644 index 81670fbe8..000000000 --- a/tests/profiler/testmetrics.nim +++ /dev/null @@ -1,273 +0,0 @@ -import math -import sequtils -import unittest2 - -import ".."/".."/chronos -import ".."/".."/chronos/profiler/metrics - -import ./utils - -suite "Profiler metrics test suite": - - setup: - installCallbacks() - - teardown: - clearRecording() - revertCallbacks() - resetTime() - - proc recordedMetrics(): ProfilerMetrics = - result.processAllEvents(rawRecording) - - test "should compute correct times for a simple blocking future": - proc simple() {.async.} = - advanceTime(50.milliseconds) - - waitFor simple() - - var metrics = recordedMetrics() - let simpleMetrics = metrics.forProc("simple") - - check simpleMetrics.execTime == 50.milliseconds - check simpleMetrics.wallClockTime == 50.milliseconds - - test "should compute correct times for a simple non-blocking future": - proc simple {.async.} = - advanceTime(10.milliseconds) - await advanceTimeAsync(50.milliseconds) - advanceTime(10.milliseconds) - - waitFor simple() - - var metrics = recordedMetrics() - let simpleMetrics = metrics.forProc("simple") - - check simpleMetrics.execTime == 20.milliseconds - check simpleMetrics.wallClockTime == 70.milliseconds - - test "should compute correct times for a non-blocking future with multiple pauses": - proc simple {.async.} = - advanceTime(10.milliseconds) - await advanceTimeAsync(50.milliseconds) - advanceTime(10.milliseconds) - await advanceTimeAsync(50.milliseconds) - advanceTime(10.milliseconds) - - waitFor simple() - - var metrics = recordedMetrics() - let simpleMetrics = metrics.forProc("simple") - - check simpleMetrics.execTime == 30.milliseconds - check simpleMetrics.wallClockTime == 130.milliseconds - - test "should compute correct times when there is a single blocking child": - proc child() {.async.} = - advanceTime(10.milliseconds) - - proc parent() {.async.} = - advanceTime(10.milliseconds) - await child() - advanceTime(10.milliseconds) - - waitFor parent() - - var metrics = recordedMetrics() - let parentMetrics = metrics.forProc("parent") - let childMetrics = metrics.forProc("child") - - check parentMetrics.execTime == 20.milliseconds - check parentMetrics.childrenExecTime == 10.milliseconds - check parentMetrics.wallClockTime == 30.milliseconds - - check childMetrics.execTime == 10.milliseconds - check childMetrics.wallClockTime == 10.milliseconds - check childMetrics.childrenExecTime == ZeroDuration - - test "should compute correct times when there is a single non-blocking child": - proc child() {.async.} = - advanceTime(10.milliseconds) - await advanceTimeAsync(50.milliseconds) - advanceTime(10.milliseconds) - - proc parent() {.async.} = - advanceTime(10.milliseconds) - await child() - advanceTime(10.milliseconds) - - waitFor parent() - - var metrics = recordedMetrics() - let parentMetrics = metrics.forProc("parent") - let childMetrics = metrics.forProc("child") - - check parentMetrics.execTime == 20.milliseconds - check parentMetrics.childrenExecTime == 20.milliseconds - check parentMetrics.wallClockTime == 90.milliseconds - - check childMetrics.execTime == 20.milliseconds - check childMetrics.wallClockTime == 70.milliseconds - check childMetrics.childrenExecTime == ZeroDuration - - test "should compute correct times when there are multiple blocking and non-blocking children": - proc blockingChild() {.async.} = - advanceTime(10.milliseconds) - - proc nonblockingChild() {.async.} = - advanceTime(10.milliseconds) - await advanceTimeAsync(20.milliseconds) - advanceTime(10.milliseconds) - - proc parent() {.async.} = - advanceTime(10.milliseconds) - await blockingChild() - advanceTime(10.milliseconds) - await nonblockingChild() - advanceTime(10.milliseconds) - await blockingChild() - advanceTime(10.milliseconds) - await nonblockingChild() - advanceTime(10.milliseconds) - - waitFor parent() - - var metrics = recordedMetrics() - - let parentMetrics = metrics.forProc("parent") - let blockingChildMetrics = metrics.forProc("blockingChild") - let nonblockingChildMetrics = metrics.forProc("nonblockingChild") - - check parentMetrics.execTime == 50.milliseconds - check parentMetrics.childrenExecTime == 60.milliseconds - check parentMetrics.wallClockTime == 150.milliseconds - - check blockingChildMetrics.execTime == 20.milliseconds - check blockingChildMetrics.wallClockTime == 20.milliseconds - check blockingChildMetrics.childrenExecTime == ZeroDuration - - check nonblockingChildMetrics.execTime == 40.milliseconds - check nonblockingChildMetrics.wallClockTime == 80.milliseconds - check nonblockingChildMetrics.childrenExecTime == ZeroDuration - - test "should compute correct times when a child throws an exception": - proc child() {.async: (raises: [CatchableError]).} = - advanceTime(10.milliseconds) - raise newException(CatchableError, "child exception") - - proc parent() {.async: (raises: [CatchableError]).} = - advanceTime(10.milliseconds) - try: - await child() - except: - discard - advanceTime(10.milliseconds) - - waitFor parent() - - var metrics = recordedMetrics() - let parentMetrics = metrics.forProc("parent") - let childMetrics = metrics.forProc("child") - - check parentMetrics.execTime == 20.milliseconds - check parentMetrics.childrenExecTime == 10.milliseconds - check parentMetrics.wallClockTime == 30.milliseconds - - check childMetrics.execTime == 10.milliseconds - check childMetrics.wallClockTime == 10.milliseconds - check childMetrics.childrenExecTime == ZeroDuration - - test "should compute correct times when a child gets cancelled": - proc child() {.async.} = - advanceTime(10.milliseconds) - await sleepAsync(1.hours) - - proc parent() {.async.} = - advanceTime(10.milliseconds) - # This is sort of subtle: we simulate that parent runs for 10 - # milliseconds before actually cancelling the child. This renders the - # test case less trivial as those 10 milliseconds should be billed as - # wallclock time at the child, causing the child's exec time and its - # wallclock time to differ. - let child = child() - advanceTime(10.milliseconds) - await child.cancelAndWait() - advanceTime(10.milliseconds) - - waitFor parent() - - var metrics = recordedMetrics() - let parentMetrics = metrics.forProc("parent") - let childMetrics = metrics.forProc("child") - - check parentMetrics.execTime == 30.milliseconds - check parentMetrics.childrenExecTime == 10.milliseconds - check parentMetrics.wallClockTime == 40.milliseconds - - check childMetrics.execTime == 10.milliseconds - check childMetrics.wallClockTime == 20.milliseconds - check childMetrics.childrenExecTime == ZeroDuration - - test "should compute the correct number of times a proc gets called": - proc child() {.async.} = discard - - proc parent() {.async.} = - for i in 1..10: - await child() - - waitFor parent() - - var metrics = recordedMetrics() - let parentMetrics = metrics.forProc("parent") - let childMetrics = metrics.forProc("child") - - check parentMetrics.callCount == 1 - check childMetrics.callCount == 10 - - test "should compute the maximum execution time for a proc, out of all calls": - var execTimes = @[10.milliseconds, 50.milliseconds, 10.milliseconds] - - proc child(d: Duration) {.async.} = - advanceTime(d) - - proc parent() {.async.} = - for d in execTimes: - await child(d) - - waitFor parent() - - var metrics = recordedMetrics() - let parentMetrics = metrics.forProc("parent") - let childMetrics = metrics.forProc("child") - - check parentMetrics.execTimeMax == ZeroDuration - check childMetrics.execTimeMax == 50.milliseconds - - test "should compute the correct execution time within finally blocks": - proc withFinally() {.async.} = - try: - advanceTime(10.milliseconds) - return - finally: - advanceTime(10.milliseconds) - await advanceTimeAsync(10.milliseconds) - advanceTime(10.milliseconds) - - waitFor withFinally() - - var metrics = recordedMetrics() - var withFinallyMetrics = metrics.forProc("withFinally") - - check withFinallyMetrics.execTime == 30.milliseconds - - test "should count futures which start in a completion state": - let completed {.used.} = Future.completed(42) - let failed {.used.} = Future[int].failed((ref ValueError)(msg: "msg")) - - var metrics = recordedMetrics() - - let stillborns = metrics.totals.pairs.toSeq.map( - proc (item: (SrcLoc, AggregateFutureMetrics)): uint = - item[1].stillbornCount).sum - - check stillborns == 2 \ No newline at end of file diff --git a/tests/profiler/utils.nim b/tests/profiler/utils.nim deleted file mode 100644 index 966a87592..000000000 --- a/tests/profiler/utils.nim +++ /dev/null @@ -1,84 +0,0 @@ -import ".."/".."/chronos -import ".."/".."/chronos/profiler - -type - SimpleEvent* = object - procedure*: string - state*: ExtendedFutureState - -# XXX this is sort of bad cause we get global state all over, but the fact we -# can't use closures on callbacks and that callbacks themselves are just -# global vars means we can't really do much better for now. -var recording*: seq[SimpleEvent] -var rawRecording*: seq[Event] -var fakeTime*: Moment = Moment.now() - -# FIXME bad, this needs to be refactored into a callback interface for the profiler. -var oldHandleFutureEvent: proc(event: Event) {.nimcall, gcsafe, raises: [].} = nil -var installed: bool = false - -proc recordEvent(event: Event) {.nimcall, gcsafe, raises: [].} = - {.cast(gcsafe).}: - recording.add( - SimpleEvent(procedure: $event.location.procedure, state: event.newState)) - - var timeShifted = event - timeShifted.timestamp = fakeTime - - rawRecording.add(timeShifted) - -proc recordSegment*(segment: string) = - {.cast(gcsafe).}: - recording.add(SimpleEvent( - procedure: segment, - state: ExtendedFutureState.Running - )) - -proc clearRecording*(): void = - recording = @[] - rawRecording = @[] - -proc installCallbacks*() = - assert not installed, "Callbacks already installed" - - enableEventCallbacks() - - oldHandleFutureEvent = handleFutureEvent - handleFutureEvent = recordEvent - - installed = true - -proc revertCallbacks*() = - assert installed, "Callbacks already uninstalled" - - handleFutureEvent = oldHandleFutureEvent - installed = false - -proc forProc*(self: var ProfilerMetrics, procedure: string): AggregateFutureMetrics = - for (key, aggMetrics) in self.totals.mpairs: - if key.procedure == procedure: - return aggMetrics - -proc resetTime*() = - fakeTime = Moment.now() - -proc advanceTime*(duration: Duration) = - fakeTime += duration - -proc advanceTimeAsync*(duration: Duration): Future[void] = - # Simulates a non-blocking operation that takes the provided duration to - # complete. - var retFuture = newFuture[void]("advanceTimeAsync") - var timer: TimerCallback - - proc completion(data: pointer) {.gcsafe.} = - if not(retFuture.finished()): - advanceTime(duration) - retFuture.complete() - - # The actual value for the timer is irrelevant, the important thing is that - # this causes the parent to pause before we advance time. - timer = setTimer(Moment.fromNow(10.milliseconds), - completion, cast[pointer](retFuture)) - - return retFuture diff --git a/tests/testall.nim b/tests/testall.nim index ccf597b7b..6419f9836 100644 --- a/tests/testall.nim +++ b/tests/testall.nim @@ -11,7 +11,7 @@ when (chronosEventEngine in ["epoll", "kqueue"]) or defined(windows): import testmacro, testsync, testsoon, testtime, testfut, testsignal, testaddress, testdatagram, teststream, testserver, testbugs, testnet, testasyncstream, testhttpserver, testshttpserver, testhttpclient, - testproc, testratelimit, testfutures, testthreadsync, testprofiler + testproc, testratelimit, testfutures, testthreadsync # Must be imported last to check for Pending futures import testutils @@ -20,7 +20,7 @@ elif chronosEventEngine == "poll": import testmacro, testsync, testsoon, testtime, testfut, testaddress, testdatagram, teststream, testserver, testbugs, testnet, testasyncstream, testhttpserver, testshttpserver, testhttpclient, - testratelimit, testfutures, testthreadsync, testprofiler + testratelimit, testfutures, testthreadsync # Must be imported last to check for Pending futures import testutils diff --git a/tests/testprofiler.nim b/tests/testprofiler.nim deleted file mode 100644 index a7f8ad553..000000000 --- a/tests/testprofiler.nim +++ /dev/null @@ -1,12 +0,0 @@ -import ../chronos/config - -when chronosProfiling: - import ../chronos/profiler - - import ./profiler/testevents - import ./profiler/testmetrics - - enableProfiling() - -{.used.} -{.warning[UnusedImport]:off.} From b26b648e90d13a91a828abcf0a4bd244f7a3c7c3 Mon Sep 17 00:00:00 2001 From: gmega Date: Fri, 1 Mar 2024 18:52:36 -0300 Subject: [PATCH 30/30] remove lines carried over from merge --- chronos/internal/asyncfutures.nim | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/chronos/internal/asyncfutures.nim b/chronos/internal/asyncfutures.nim index 9a7261db5..b3a6a3820 100644 --- a/chronos/internal/asyncfutures.nim +++ b/chronos/internal/asyncfutures.nim @@ -192,11 +192,11 @@ 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 chronosProfiling: if not isNil(onBaseFutureEvent): onBaseFutureEvent(fut, state) - when chronosStrictFutureAccess: - doAssert fut.internalCancelcb == nil or state != FutureState.Cancelled + fut.internalCancelcb = nil # release cancellation callback memory for item in fut.internalCallbacks.mitems(): if not(isNil(item.function)):