initial port of profiler to Chronos V4

chronos/config.nim

@@ -31,7 +31,12 @@ const
   chronosStackTrace* {.booldefine.}: bool = defined(chronosDebug)
     ## Include stack traces in futures for creation and completion points
 
-  chronosFutureId* {.booldefine.}: bool = defined(chronosDebug)
+  chronosProfiling* {.booldefine.} = defined(chronosProfiling)
+    ## Enable instrumentation callbacks which are called at
+    ## the start, pause, or end of a Future's lifetime.
+    ## Useful for implementing metrics or other instrumentation.
+
+  chronosFutureId* {.booldefine.}: bool = defined(chronosDebug) or chronosProfiling
     ## Generate a unique `id` for every future - when disabled, the address of
     ## the future will be used instead
 
@@ -56,11 +61,6 @@ const
     ## using `AsyncProcessOption.EvalCommand` and API calls such as
     ## ``execCommand(command)`` and ``execCommandEx(command)``.
 
-  chronosProfiling* {.booldefine.} = defined(chronosProfiling)
-    ## Enable instrumentation callbacks which are called at
-    ## the start, pause, or end of a Future's lifetime.
-    ## Useful for implementing metrics or other instrumentation.
-
   chronosEventsCount* {.intdefine.} = 64
     ## Number of OS poll events retrieved by syscall (epoll, kqueue, poll).
 
@@ -89,7 +89,6 @@ when defined(chronosStrictException):
   # In chronos v3, this setting was used as the opposite of
   # `chronosHandleException` - the setting is deprecated to encourage
   # migration to the new mode.
->>>>>>> master
 
 when defined(debug) or defined(chronosConfig):
   import std/macros

chronos/profiler/events.nim

@@ -1,11 +1,10 @@
 ## This module defines the lower-level callback implementations that hook into
 ## the Chronos scheduler when profiling is enabled. The main goal is to provide
-## timestamped events changes for futures while allowing a simpler implementation
-## (only one event object type) for the remainder of the profiler.
+## timestamped state changes for futures, which form the input for the profiler.
 
-import ".."/timer
-import ".."/futures
-import ".."/srcloc
+import ../timer
+import ../futures
+import ../srcloc
 
 type
   ExtendedFutureState* {.pure.} = enum

chronos/profiler/metrics.nim

@@ -13,7 +13,6 @@ type
     execTimeMax*: Duration
     childrenExecTime*: Duration
     wallClockTime*: Duration
-    zombieEventCount*: uint
     stillbornCount*: uint
     callCount*: uint
 
@@ -68,29 +67,8 @@ proc bindParent(self: var ProfilerMetrics, metrics: ptr RunningFuture): void =
     assert metrics.parent.get == current.get
   metrics.parent = current
 
-proc isZombie(self: var ProfilerMetrics, event: Event): bool =
-  # The first precondition for a zombie future is that it should not have
-  # an entry in the partial metrics table.
-  if self.partials.hasKey(event.futureId):
-    return false
-
-  # The second precondition is that it must have been completed at least once.
-  # Since we're not tracking IDs for individual completed futures cause that 
-  # would use up a lot of memory, we test if at least one future of this "type"
-  # (i.e. at the same location) has been completed. If that's not satisfied,
-  # this positively is a bug.
-  assert self.totals.hasKey(event.location), $event.location
-
-  self.totals.withValue(event.location, aggMetrics):
-    # Count zombie events. We can't tell how many events are issued by a single
-    # zombie future (we think it's one, but who knows) so can't really rely on 
-    # this being a count of the actual zombie futures.
-    aggMetrics.zombieEventCount.inc()
-
-  true
-
 proc futureRunning(self: var ProfilerMetrics, event: Event): void =
-  if self.isZombie(event): return
+  assert self.partials.hasKey(event.futureId), $event.location
 
   self.partials.withValue(event.futureId, metrics):
     assert metrics.state == Pending or metrics.state == Paused,
@@ -103,9 +81,8 @@ proc futureRunning(self: var ProfilerMetrics, event: Event): void =
     metrics.state = Running
 
 proc futurePaused(self: var ProfilerMetrics, event: Event): void = 
-  if self.isZombie(event): return
-
   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

tests/profiler/testevents.nim

@@ -109,30 +109,25 @@ suite "Profiler hooks test suite":
     ]
 
   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:
-          recordSegment("segment 1")
-          await sleepAsync(10.milliseconds)
-          # both segments must run
-          recordSegment("segment 2")
+    proc withFinally(): Future[void] {.async.} =
+      try:
+        return
+      finally:
+        recordSegment("segment 1")
+        await sleepAsync(10.milliseconds)
+        # both segments must run
+        recordSegment("segment 2")
 
-      waitFor withFinally()
+    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"),
-      ]
+    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/profiler/testmetrics.nim

@@ -151,11 +151,11 @@ suite "Profiler metrics test suite":
       check nonblockingChildMetrics.childrenExecTime == ZeroDuration
 
     test "should compute correct times when a child throws an exception":
-      proc child() {.async.} =
+      proc child() {.async: (raises: [CatchableError]).} =
         advanceTime(10.milliseconds)
-        raise newException(Exception, "child exception")
+        raise newException(CatchableError, "child exception")
 
-      proc parent() {.async.} =
+      proc parent() {.async: (raises: [CatchableError]).} =
         advanceTime(10.milliseconds)
         try:
           await child()
@@ -243,22 +243,22 @@ suite "Profiler metrics test suite":
       check parentMetrics.execTimeMax == ZeroDuration
       check childMetrics.execTimeMax == 50.milliseconds
 
-    test "should count zombie futures and measure their non-zombie execution time":
-      proc zombie() {.async.} =
+    test "should compute the correct execution time within finally blocks":
+      proc withFinally() {.async.} =
         try:
           advanceTime(10.milliseconds)
           return
         finally:
-          advanceTime(10.milliseconds) # this is ran in zombie mode
+          advanceTime(10.milliseconds)
           await advanceTimeAsync(10.milliseconds)
+          advanceTime(10.milliseconds)
 
-      waitFor zombie()
+      waitFor withFinally()
 
       var metrics = recordedMetrics()
-      var zombieMetrics = metrics.forProc("zombie")
+      var withFinallyMetrics = metrics.forProc("withFinally")
 
-      check zombieMetrics.execTime == 10.milliseconds
-      check zombieMetrics.zombieEventCount == 1
+      check withFinallyMetrics.execTime == 30.milliseconds
 
     test "should count futures which start in a completion state":
       let completed {.used.} = Future.completed(42)