import tests

tests/profiler/example.nim

@@ -0,0 +1,18 @@
+import os
+import ../../chronos
+
+proc child11() {.async.} =
+  echo "I ran"
+  await sleepAsync(10.milliseconds)
+
+proc child2() {.async.} = 
+  os.sleep(10)
+
+proc child1() {.async.} =
+  await child2()
+  await child11()
+
+proc p() {.async.} =
+  echo "r1"
+  await child1()
+  echo "r2"

tests/profiler/testevents.nim

@@ -0,0 +1,134 @@
+import std/os
+
+import unittest2
+
+import ".."/".."/chronos
+import ".."/".."/chronos/profiler
+
+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":
+    skip()
+    when false:
+      # TODO: chronos allows completed futures to generate children in their
+      #   finally blocks. This causes a set of transitions that break our state
+      #   machine.
+      proc withFinally(): Future[void] {.async.} =
+        try:
+          return
+        finally:
+          await sleepAsync(10.milliseconds)
+
+      waitFor withFinally()
+
+      check recording == @[
+        SimpleEvent(state: Pending, procedure: "withFinally"),
+        SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"),
+        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")
+      ]

tests/profiler/testmetrics.nim

@@ -0,0 +1,242 @@
+import unittest2
+
+import ".."/".."/chronos
+import ".."/".."/chronos/profiler/metrics
+
+import ./utils
+
+suite "profiler metrics test suite":
+  
+    setup:
+      installCallbacks()
+
+    teardown:
+      clearRecording()
+      revertCallbacks()
+      resetTime()
+
+    proc recordedMetrics(): ProfilerMetrics = 
+      result.processAllEvents(rawRecording)
+  
+    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.} =
+        advanceTime(10.milliseconds)
+        raise newException(Exception, "child exception")
+
+      proc parent() {.async.} =
+        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

tests/profiler/utils.nim

@@ -0,0 +1,84 @@
+import ".."/".."/chronos
+import ".."/".."/chronos/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()
+
+# FIXME bad, this needs to be refactored into a callback interface for the profiler.
+var oldHandleFutureEvent: proc(event: Event) {.nimcall, gcsafe, raises: [].} = nil
+var installed: bool = false
+
+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 not installed, "Callbacks already installed"
+
+  enableEventCallbacks()
+
+  oldHandleFutureEvent = handleFutureEvent
+  handleFutureEvent = recordEvent
+
+  installed = true
+
+proc revertCallbacks*() =
+  assert installed, "Callbacks already uninstalled"
+  
+  handleFutureEvent = oldHandleFutureEvent
+  installed = false
+
+proc forProc*(self: var ProfilerMetrics, procedure: string): AggregateFutureMetrics =
+  for (key, aggMetrics) in self.totals.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

tests/testprofiler.nim

@@ -0,0 +1,10 @@
+import ../chronos/config
+
+when chronosProfiling:
+  import ../chronos/profiler
+
+  import ./profiler/testevents
+  import ./profiler/testmetrics
+
+{.used.}
+{.warning[UnusedImport]:off.}