initial import

chroprof.nim

@@ -0,0 +1,6 @@
+when not defined(chronosProfiling):
+  {.error: "chronprof requires -d:chronosProfiling to be enabled".}
+
+import ./chroprof/api
+
+export api

chroprof.nimble

@@ -0,0 +1,11 @@
+mode = ScriptMode.Verbose
+
+packageName = "chroprof"
+version     = "0.1.0"
+author      = "Status Research & Development GmbH"
+description = "A profiling tool for the Chronos networking framework"
+license     = "MIT or Apache License 2.0"
+skipDirs    = @["tests"]
+
+requires "nim >= 1.6.16",
+         "https://github.com/codex-storage/nim-chronos#feature/profiler-v4"

chroprof/api.nim

@@ -0,0 +1,21 @@
+import chronos/futures
+import ./[profiler, events]
+
+type EventCallback = proc (e: Event) {.nimcall, gcsafe, raises: [].}
+
+var profilerInstance {.threadvar.}: ProfilerState
+
+proc getMetrics*(): MetricsTotals = 
+  ## Returns the `MetricsTotals` for the event loop running in the 
+  ## current thread.
+  result = profilerInstance.metrics
+
+proc enableEventCallbacks*(callback: EventCallback): void =
+  onBaseFutureEvent = handleBaseFutureEvent
+  onAsyncFutureEvent = handleAsyncFutureEvent
+  handleFutureEvent = callback
+    
+proc enableProfiling*() =
+  ## Enables profiling for the the event loop running in the current thread.
+  handleFutureEvent = proc (e: Event) {.nimcall.} = 
+    profilerInstance.processEvent(e)

chroprof/events.nim

@@ -0,0 +1,62 @@
+## This module provides the callbacks that hook into Chronos and record 
+## timestamped events on Future state transitions. It also consolidates 
+## the FutureState and AsyncFutureState into a single enum to ease downstream
+## processing.
+## 
+## This is an internal module and none of what is here should be considered API.
+
+import chronos/[timer, futures, srcloc]
+
+type
+  ExtendedFutureState* {.pure.} = enum
+    Pending,
+    Running,
+    Paused,
+    Completed,
+    Cancelled,
+    Failed,
+
+  Event* = object
+    future: FutureBase
+    newState*: ExtendedFutureState
+    timestamp*: Moment
+  
+var handleFutureEvent* {.threadvar.}: proc (event: Event) {.nimcall, gcsafe, raises: [].}
+
+proc `location`*(self: Event): SrcLoc =
+  self.future.internalLocation[Create][]
+
+proc `futureId`*(self: Event): uint =
+  self.future.id
+
+proc mkEvent(future: FutureBase, state: ExtendedFutureState): Event =
+  Event(
+    future: future,
+    newState: state,
+    timestamp: Moment.now(),
+  )
+  
+proc handleBaseFutureEvent*(future: FutureBase,
+    state: FutureState): void {.nimcall.} =
+  {.cast(gcsafe).}:
+    let extendedState = case state:
+      of FutureState.Pending: ExtendedFutureState.Pending
+      of FutureState.Completed: ExtendedFutureState.Completed
+      of FutureState.Cancelled: ExtendedFutureState.Cancelled
+      of FutureState.Failed: ExtendedFutureState.Failed
+
+    if not isNil(handleFutureEvent):
+      handleFutureEvent(mkEvent(future, extendedState))
+
+proc handleAsyncFutureEvent*(future: FutureBase,
+    state: AsyncFutureState): void {.nimcall.} =
+  {.cast(gcsafe).}:
+    let extendedState = case state:
+      of AsyncFutureState.Running: ExtendedFutureState.Running
+      of AsyncFutureState.Paused: ExtendedFutureState.Paused
+
+    if not isNil(handleFutureEvent):
+      handleFutureEvent(mkEvent(future, extendedState))
+
+
+

chroprof/profiler.nim

@@ -0,0 +1,167 @@
+## This module contains the actual profiler implementation - the piece of code
+## responsible for computing and aggregating metrics from timestamped event 
+## sequences.
+## 
+import std/[tables, options, sets]
+import chronos/[timer, srcloc]
+
+import ./events
+
+export timer, tables, sets, srcloc
+
+type
+  FutureType* = SrcLoc 
+    ## Within the scope of the profiler, a source location identifies
+    ## a future type. 
+
+  AggregateMetrics* = object
+    ## Stores aggregate metrics for a given `FutureType`.
+    execTime*: Duration           ## The total time that `Future`s of a given
+                                  ## `FutureType` actually ran; i.e., actively 
+                                  ## occupied the event loop thread, summed 
+                                  ## accross all such `Futures`.
+    
+    execTimeMax*: Duration        ## The maximum time that a `Future` of a
+                                  ## given `FutureType` actually ran; i.e.,
+                                  ## actively occupied the event loop thread.
+    
+    childrenExecTime*: Duration   ## Total time that the children of `Future`s
+                                  ## of this `FutureType` actually ran; i.e., 
+                                  ## actively occupied the event loop thread, 
+                                  ## summed across all such children.
+    
+    wallClockTime*: Duration      ## Total time that the Future was alive; 
+                                  ## i.e., the time between the Future's 
+                                  ## creation and its completion, summed 
+                                  ## across all runs of this `FutureType`.
+                                  
+    stillbornCount*: uint         ## Number of futures of this `FutureType` 
+                                  ## that were born in a finished state; 
+                                  ## i.e., a `FutureState` that is not Pending.
+    
+    callCount*: uint              ## Total number of distinct `Future`s observed
+                                  ## for this `FutureType`.
+
+  PartialMetrics* = object
+    state*: ExtendedFutureState
+    created*: Moment
+    lastStarted*: Moment
+    timeToFirstPause*: Duration
+    partialExecTime*: Duration
+    partialChildrenExecTime*: Duration
+    partialChildrenExecOverlap*: Duration
+    parent*: Option[uint]
+    pauses*: uint
+
+  MetricsTotals* = Table[SrcLoc, AggregateMetrics]
+
+  ProfilerState* = object
+    callStack: seq[uint]
+    partials: Table[uint, PartialMetrics]
+    metrics*: MetricsTotals
+
+proc `execTimeWithChildren`*(self: AggregateMetrics): Duration =
+  self.execTime + self.childrenExecTime
+
+proc push(self: var seq[uint], value: uint): void = self.add(value)
+
+proc pop(self: var seq[uint]): uint =
+  let value = self[^1]
+  self.setLen(self.len - 1)
+  value
+
+proc peek(self: var seq[uint]): Option[uint] =
+  if self.len == 0: none(uint) else: self[^1].some
+
+proc `$`(location: SrcLoc): string =
+  $location.procedure & "[" & $location.file & ":" & $location.line & "]"
+
+proc futureCreated(self: var ProfilerState, event: Event): void =
+  assert not self.partials.hasKey(event.futureId), $event.location
+
+  self.partials[event.futureId] = PartialMetrics(
+    created: event.timestamp,
+    state: Pending,
+  )
+
+proc bindParent(self: var ProfilerState, metrics: ptr PartialMetrics): void =
+  let current = self.callStack.peek()
+  if current.isNone:
+    return
+
+  if metrics.parent.isSome:
+    assert metrics.parent.get == current.get
+  metrics.parent = current
+
+proc futureRunning(self: var ProfilerState, event: Event): void =
+  assert self.partials.hasKey(event.futureId), $event.location
+
+  self.partials.withValue(event.futureId, metrics):
+    assert metrics.state == Pending or metrics.state == Paused,
+      $event.location & " " & $metrics.state
+
+    self.bindParent(metrics)
+    self.callStack.push(event.futureId)
+
+    metrics.lastStarted = event.timestamp
+    metrics.state = Running
+
+proc futurePaused(self: var ProfilerState, event: Event): void = 
+  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
+
+    let segmentExecTime = event.timestamp - metrics.lastStarted
+
+    if metrics.pauses == 0:
+      metrics.timeToFirstPause = segmentExecTime
+    metrics.partialExecTime += segmentExecTime
+    metrics.pauses += 1
+    metrics.state = Paused
+
+proc futureCompleted(self: var ProfilerState, event: Event): void =
+  let location = event.location
+  if not self.metrics.hasKey(location):
+    self.metrics[location] = AggregateMetrics()
+
+  self.metrics.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
+
+    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
+
+  self.partials.del(event.futureId)
+
+proc processEvent*(self: var ProfilerState, event: Event): void =
+  case event.newState:
+  of Pending: self.futureCreated(event)
+  of Running: self.futureRunning(event)
+  of Paused: self.futurePaused(event)
+  # Completion, failure and cancellation are currently handled the same way.
+  of Completed: self.futureCompleted(event)
+  of Failed: self.futureCompleted(event)
+  of Cancelled: self.futureCompleted(event)
+
+proc processAllEvents*(self: var ProfilerState, events: seq[Event]): void =
+  for event in events:
+    self.processEvent(event)

config.nims

@@ -0,0 +1 @@
+--d:chronosProfiling

tests/testevents.nim

@@ -0,0 +1,132 @@
+import std/os
+
+import chronos
+import unittest2
+
+import pkg/chroprof/events
+import ./utils
+
+suite "Profiler hooks test suite":
+
+  setup:
+    installCallbacks()
+
+  teardown:
+    clearRecording()
+    revertCallbacks() 
+
+  test "should emit correct events for a simple future":
+    
+    proc simple() {.async.} =
+      os.sleep(1)
+      
+    waitFor simple()
+
+    check recording == @[
+      SimpleEvent(state: Pending, procedure: "simple"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "simple"),
+      SimpleEvent(state: Completed, procedure: "simple"),
+    ]
+
+  test "should emit correct events when a single child runs as part of the parent":
+
+    proc withChildren() {.async.} =
+      recordSegment("segment 1")
+      await sleepAsync(10.milliseconds)
+      recordSegment("segment 2")
+      
+    waitFor withChildren()
+
+    check recording == @[
+      SimpleEvent(state: Pending, procedure: "withChildren"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"),
+      SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"),
+      SimpleEvent(state: Paused, procedure: "withChildren"),
+      SimpleEvent(state: Completed, procedure: "chronos.sleepAsync(Duration)"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"),
+      SimpleEvent(state: Completed, procedure: "withChildren"),
+    ]
+
+  test "should emit correct events when a nested child pauses execution":
+    proc child2() {.async.} =
+      recordSegment("segment 21")
+      await sleepAsync(10.milliseconds)
+      recordSegment("segment 22")
+      await sleepAsync(10.milliseconds)
+      recordSegment("segment 23")
+
+    proc child1() {.async.} =
+      recordSegment("segment 11")
+      await child2()
+      recordSegment("segment 12")
+
+    proc withChildren() {.async.} =
+      recordSegment("segment 1")
+      await child1()
+      recordSegment("segment 2")
+            
+    waitFor withChildren()
+
+    check recording == @[
+      # First iteration of parent and each child
+      SimpleEvent(state: Pending, procedure: "withChildren"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"),
+      SimpleEvent(state: ExtendedFutureState.Pending, procedure: "child1"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "child1"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 11"),
+      SimpleEvent(state: ExtendedFutureState.Pending, procedure: "child2"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "child2"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 21"),
+      SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"),
+      SimpleEvent(state: ExtendedFutureState.Paused, procedure: "child2"),
+      SimpleEvent(state: ExtendedFutureState.Paused, procedure: "child1"),
+      SimpleEvent(state: ExtendedFutureState.Paused, procedure: "withChildren"),
+
+      # Second iteration of child2
+      SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "child2"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 22"),
+      SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"),
+      SimpleEvent(state: ExtendedFutureState.Paused, procedure: "child2"),
+      SimpleEvent(state: ExtendedFutureState.Completed, procedure: "chronos.sleepAsync(Duration)"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "child2"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 23"),
+      SimpleEvent(state: ExtendedFutureState.Completed, procedure: "child2"),
+
+      # Second iteration child1
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "child1"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 12"),
+      SimpleEvent(state: ExtendedFutureState.Completed, procedure: "child1"),
+
+      # Second iteration of parent
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"),
+      SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"),
+      SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withChildren"),
+    ]
+
+  test "should not say a future is completed before children in finally blocks are run":
+    proc withFinally(): Future[void] {.async.} =
+      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.Running, procedure: "segment 2"),
+      SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withFinally"),
+    ]

tests/testprofiler.nim

@@ -0,0 +1,275 @@
+import math
+import sequtils
+import unittest2
+
+import chronos
+import chroprof/profiler
+
+import ./utils
+
+suite "Profiler metrics test suite":
+  
+    setup:
+      installCallbacks()
+
+    teardown:
+      clearRecording()
+      revertCallbacks()
+      resetTime()
+
+    proc recordedMetrics(): MetricsTotals = 
+      var profiler: ProfilerState
+      profiler.processAllEvents(rawRecording)
+      profiler.metrics
+  
+    test "should compute correct times for a simple blocking future":
+      proc simple() {.async.} =
+        advanceTime(50.milliseconds)
+        
+      waitFor simple()
+
+      var metrics = recordedMetrics()
+      let simpleMetrics = metrics.forProc("simple")
+      
+      check simpleMetrics.execTime == 50.milliseconds
+      check simpleMetrics.wallClockTime == 50.milliseconds
+
+    test "should compute correct times for a simple non-blocking future":
+      proc simple {.async.} =
+        advanceTime(10.milliseconds)
+        await advanceTimeAsync(50.milliseconds)
+        advanceTime(10.milliseconds)
+
+      waitFor simple()
+
+      var metrics = recordedMetrics()
+      let simpleMetrics = metrics.forProc("simple")
+
+      check simpleMetrics.execTime == 20.milliseconds
+      check simpleMetrics.wallClockTime == 70.milliseconds
+
+    test "should compute correct times for a non-blocking future with multiple pauses":
+      proc simple {.async.} =
+        advanceTime(10.milliseconds)
+        await advanceTimeAsync(50.milliseconds)
+        advanceTime(10.milliseconds)
+        await advanceTimeAsync(50.milliseconds)
+        advanceTime(10.milliseconds)
+
+      waitFor simple()
+
+      var metrics = recordedMetrics()
+      let simpleMetrics = metrics.forProc("simple")
+
+      check simpleMetrics.execTime == 30.milliseconds
+      check simpleMetrics.wallClockTime == 130.milliseconds
+
+    test "should compute correct times when there is a single blocking child":
+      proc child() {.async.} = 
+        advanceTime(10.milliseconds)
+
+      proc parent() {.async.} =
+        advanceTime(10.milliseconds)
+        await child()
+        advanceTime(10.milliseconds)
+        
+      waitFor parent()
+
+      var metrics = recordedMetrics()
+      let parentMetrics = metrics.forProc("parent")
+      let childMetrics = metrics.forProc("child")
+
+      check parentMetrics.execTime == 20.milliseconds
+      check parentMetrics.childrenExecTime == 10.milliseconds
+      check parentMetrics.wallClockTime == 30.milliseconds
+
+      check childMetrics.execTime == 10.milliseconds
+      check childMetrics.wallClockTime == 10.milliseconds
+      check childMetrics.childrenExecTime == ZeroDuration
+
+    test "should compute correct times when there is a single non-blocking child":
+      proc child() {.async.} =
+        advanceTime(10.milliseconds)
+        await advanceTimeAsync(50.milliseconds)
+        advanceTime(10.milliseconds)
+
+      proc parent() {.async.} =
+        advanceTime(10.milliseconds)
+        await child()
+        advanceTime(10.milliseconds)
+
+      waitFor parent()
+
+      var metrics = recordedMetrics()
+      let parentMetrics = metrics.forProc("parent")
+      let childMetrics = metrics.forProc("child")
+
+      check parentMetrics.execTime == 20.milliseconds
+      check parentMetrics.childrenExecTime == 20.milliseconds
+      check parentMetrics.wallClockTime == 90.milliseconds
+
+      check childMetrics.execTime == 20.milliseconds
+      check childMetrics.wallClockTime == 70.milliseconds
+      check childMetrics.childrenExecTime == ZeroDuration
+
+    test "should compute correct times when there are multiple blocking and non-blocking children":
+      proc blockingChild() {.async.} = 
+        advanceTime(10.milliseconds)
+
+      proc nonblockingChild() {.async.} =
+        advanceTime(10.milliseconds)
+        await advanceTimeAsync(20.milliseconds)
+        advanceTime(10.milliseconds)
+
+      proc parent() {.async.} =
+        advanceTime(10.milliseconds)
+        await blockingChild()
+        advanceTime(10.milliseconds)
+        await nonblockingChild()
+        advanceTime(10.milliseconds)
+        await blockingChild()
+        advanceTime(10.milliseconds)
+        await nonblockingChild()
+        advanceTime(10.milliseconds)
+
+      waitFor parent()
+
+      var metrics = recordedMetrics()
+
+      let parentMetrics = metrics.forProc("parent")
+      let blockingChildMetrics = metrics.forProc("blockingChild")
+      let nonblockingChildMetrics = metrics.forProc("nonblockingChild")
+
+      check parentMetrics.execTime == 50.milliseconds
+      check parentMetrics.childrenExecTime == 60.milliseconds
+      check parentMetrics.wallClockTime == 150.milliseconds
+
+      check blockingChildMetrics.execTime == 20.milliseconds
+      check blockingChildMetrics.wallClockTime == 20.milliseconds
+      check blockingChildMetrics.childrenExecTime == ZeroDuration
+      
+      check nonblockingChildMetrics.execTime == 40.milliseconds
+      check nonblockingChildMetrics.wallClockTime == 80.milliseconds
+      check nonblockingChildMetrics.childrenExecTime == ZeroDuration
+
+    test "should compute correct times when a child throws an exception":
+      proc child() {.async: (raises: [CatchableError]).} =
+        advanceTime(10.milliseconds)
+        raise newException(CatchableError, "child exception")
+
+      proc parent() {.async: (raises: [CatchableError]).} =
+        advanceTime(10.milliseconds)
+        try:
+          await child()
+        except:
+          discard
+        advanceTime(10.milliseconds)
+
+      waitFor parent()
+
+      var metrics = recordedMetrics()
+      let parentMetrics = metrics.forProc("parent")
+      let childMetrics = metrics.forProc("child")
+
+      check parentMetrics.execTime == 20.milliseconds
+      check parentMetrics.childrenExecTime == 10.milliseconds
+      check parentMetrics.wallClockTime == 30.milliseconds
+
+      check childMetrics.execTime == 10.milliseconds
+      check childMetrics.wallClockTime == 10.milliseconds
+      check childMetrics.childrenExecTime == ZeroDuration
+
+    test "should compute correct times when a child gets cancelled":
+      proc child() {.async.} =
+        advanceTime(10.milliseconds)
+        await sleepAsync(1.hours)
+
+      proc parent() {.async.} =
+        advanceTime(10.milliseconds)
+        # This is sort of subtle: we simulate that parent runs for 10
+        # milliseconds before actually cancelling the child. This renders the
+        # test case less trivial as those 10 milliseconds should be billed as 
+        # wallclock time at the child, causing the child's exec time and its
+        # wallclock time to differ.
+        let child = child()
+        advanceTime(10.milliseconds)
+        await child.cancelAndWait()
+        advanceTime(10.milliseconds)
+
+      waitFor parent()
+
+      var metrics = recordedMetrics()
+      let parentMetrics = metrics.forProc("parent")
+      let childMetrics = metrics.forProc("child")
+
+      check parentMetrics.execTime == 30.milliseconds
+      check parentMetrics.childrenExecTime == 10.milliseconds
+      check parentMetrics.wallClockTime == 40.milliseconds
+
+      check childMetrics.execTime == 10.milliseconds
+      check childMetrics.wallClockTime == 20.milliseconds
+      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
+
+    test "should compute the correct execution time within finally blocks":
+      proc withFinally() {.async.} =
+        try:
+          advanceTime(10.milliseconds)
+          return
+        finally:
+          advanceTime(10.milliseconds)
+          await advanceTimeAsync(10.milliseconds)
+          advanceTime(10.milliseconds)
+
+      waitFor withFinally()
+
+      var metrics = recordedMetrics()
+      var withFinallyMetrics = metrics.forProc("withFinally")
+
+      check withFinallyMetrics.execTime == 30.milliseconds
+
+    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.pairs.toSeq.map(
+        proc (item: (SrcLoc, AggregateMetrics)): uint =
+          item[1].stillbornCount).sum
+
+      check stillborns == 2

tests/utils.nim

@@ -0,0 +1,74 @@
+import chronos
+import pkg/chroprof/[api, events, profiler]
+
+type
+  SimpleEvent* = object
+    procedure*: string
+    state*: ExtendedFutureState
+
+# XXX this is sort of bad cause we get global state all over, but the fact we
+#   can't use closures on callbacks and that callbacks themselves are just
+#   global vars means we can't really do much better for now.
+var recording*: seq[SimpleEvent]
+var rawRecording*: seq[Event]
+var fakeTime*: Moment = Moment.now()
+
+proc recordEvent(event: Event) {.nimcall, gcsafe, raises: [].} =
+  {.cast(gcsafe).}:
+    recording.add(
+      SimpleEvent(procedure: $event.location.procedure, state: event.newState))
+
+    var timeShifted = event
+    timeShifted.timestamp = fakeTime
+
+    rawRecording.add(timeShifted)
+
+proc recordSegment*(segment: string) =
+  {.cast(gcsafe).}:
+    recording.add(SimpleEvent(
+      procedure: segment,
+      state: ExtendedFutureState.Running
+    ))
+
+proc clearRecording*(): void =
+  recording = @[]
+  rawRecording = @[]
+
+proc installCallbacks*() =
+  assert isNil(handleFutureEvent), "There is a callback already installed"
+
+  enableEventCallbacks(recordEvent)
+
+proc revertCallbacks*() =
+  assert not isNil(handleFutureEvent), "There are no callbacks installed"
+  
+  handleFutureEvent = nil
+
+proc forProc*(self: var MetricsTotals, procedure: string): AggregateMetrics =
+  for (key, aggMetrics) in self.mpairs:
+    if key.procedure == procedure:
+      return aggMetrics
+
+proc resetTime*() =
+  fakeTime = Moment.now()
+
+proc advanceTime*(duration: Duration) =
+  fakeTime += duration
+
+proc advanceTimeAsync*(duration: Duration): Future[void] = 
+  # Simulates a non-blocking operation that takes the provided duration to 
+  # complete.
+  var retFuture = newFuture[void]("advanceTimeAsync")
+  var timer: TimerCallback
+
+  proc completion(data: pointer) {.gcsafe.} =
+    if not(retFuture.finished()):
+      advanceTime(duration)
+      retFuture.complete()
+
+  # The actual value for the timer is irrelevant, the important thing is that 
+  # this causes the parent to pause before we advance time.
+  timer = setTimer(Moment.fromNow(10.milliseconds), 
+    completion, cast[pointer](retFuture))
+
+  return retFuture