enable profiling on testprofiler; import/export profiler from chronos's root module

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

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:

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

tests/testprofiler.nim

@@ -6,5 +6,7 @@ when chronosProfiling:
   import ./profiler/testevents
   import ./profiler/testmetrics
 
+  enableProfiling()
+
 {.used.}
 {.warning[UnusedImport]:off.}