diff --git a/chronos.nim b/chronos.nim index 6801b28..7388f16 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 b7e38db..6173616 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 + let location = event.location + if not self.totals.hasKey(location): + self.totals[location] = AggregateFutureMetrics() - self.partials.withValue(event.futureId, metrics): - if metrics.state == Running: - self.futurePaused(event) + 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 - 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 + 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 5090c98..cc400bb 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 e5b1a10..a7f8ad5 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.}