diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index 4c22bd1..58a2cb1 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 86c21f7..8d11228 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 348914e..5d69264 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