diff --git a/chronos/profiler.nim b/chronos/profiler.nim index 25bf70f..1f43f11 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 bf5dca8..aedb33f 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 4ccc809..348914e 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