From f007e1b0fd956591c5fae9040a6c0d11c6ec61cb Mon Sep 17 00:00:00 2001 From: gmega Date: Wed, 31 Jan 2024 11:17:33 -0300 Subject: [PATCH] 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 | 45 +++++++++++++++------------------- tests/profiler/testmetrics.nim | 20 +++++++-------- 5 files changed, 42 insertions(+), 72 deletions(-) diff --git a/chronos/config.nim b/chronos/config.nim index 9c07d2e..57571b1 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 f04f7fc..6d363d2 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 6173616..1c19763 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 3b9b957..973439f 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") + proc withFinally(): Future[void] {.async.} = + try: + return + finally: + recordSegment("segment 1") + await sleepAsync(10.milliseconds) + # both segments must run + recordSegment("segment 2") - waitFor withFinally() + 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"), - ] + 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 cc400bb..81670fb 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)