change enable flag to "chronosProfiling"; add "enable" profiler proc; add stronger assertions to event tests"

chronos.nimble

@@ -48,3 +48,11 @@ task test_libbacktrace, "test with libbacktrace":
 
   for args in allArgs:
     run args, "tests/testall"
+
+task test_profiler, "test with profiler instrumentation":
+  var allArgs = @[
+      "-d:release -d:chronosProfiling",
+    ]
+
+  for args in allArgs:
+    run args, "tests/testall"

chronos/asyncfutures2.nim

@@ -132,7 +132,7 @@ proc finish(fut: FutureBase, state: FutureState) =
   # 1. `finish()` is a private procedure and `state` is under our control.
   # 2. `fut.state` is checked by `checkFinished()`.
   fut.internalState = state
-  when chronosFuturesInstrumentation:
+  when chronosProfiling:
     if not isNil(onFutureEvent):
       onFutureEvent(fut, state)
   when chronosStrictFutureAccess:
@@ -316,7 +316,7 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} =
   var next: FutureBase
   template iterate =
     while true:
-      when chronosFuturesInstrumentation:
+      when chronosProfiling:
         if not isNil(onFutureExecEvent):
           onFutureExecEvent(fut, Running)
 
@@ -328,7 +328,7 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} =
         break
       
       # If we got thus far, means the future is paused.
-      when chronosFuturesInstrumentation:
+      when chronosProfiling:
         if not isNil(onFutureExecEvent):
           onFutureExecEvent(fut, Paused)
 

chronos/config.nim

@@ -49,7 +49,7 @@ when (NimMajor, NimMinor) >= (1, 4):
       ## using `AsyncProcessOption.EvalCommand` and API calls such as
       ## ``execCommand(command)`` and ``execCommandEx(command)``.
 
-    chronosFuturesInstrumentation* {.booldefine.} = defined(chronosFuturesInstrumentation)
+    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.
@@ -66,7 +66,7 @@ else:
     chronosFutureTracking*: bool =
       defined(chronosDebug) or defined(chronosFutureTracking)
     chronosDumpAsync*: bool = defined(nimDumpAsync)
-    chronosFuturesInstrumentation*: bool = defined(chronosFuturesInstrumentation)
+    chronosProfiling*: bool = defined(chronosProfiling)
     chronosProcShell* {.strdefine.}: string =
       when defined(windows):
         "cmd.exe"

chronos/futures.nim

@@ -93,7 +93,7 @@ when chronosFutureTracking:
 
   var futureList* {.threadvar.}: FutureList
 
-when chronosFuturesInstrumentation:
+when chronosProfiling:
   type FutureExecutionState* {.pure.} = enum 
     Running, Paused
 
@@ -128,7 +128,7 @@ proc internalInitFutureBase*(
         futureList.head = fut
       futureList.count.inc()
 
-  when chronosFuturesInstrumentation:
+  when chronosProfiling:
     if not isNil(onFutureEvent):
       onFutureEvent(fut, state)
 

chronos/profiler.nim

@@ -0,0 +1,28 @@
+import ./config
+
+when chronosProfiling:
+  import futures
+  import ./profiler/[events, metrics]
+
+  export futures, events, metrics
+
+  when not defined(chronosFutureId):
+    {.error "chronosProfiling requires chronosFutureId to be enabled".}
+
+  var futureMetrics {.threadvar.}: ProfilerMetrics 
+
+  proc getMetrics*(): ProfilerMetrics = 
+    ## Returns metrics for the current event loop.
+    result = futureMetrics
+
+  proc enableEventCallbacks*(): void =
+    onFutureEvent = handleFutureEventCB
+    onFutureExecEvent = handleFutureExecEventCB
+    
+  proc enable*() = 
+    ## Enables profiling on the current event loop.
+    if not isNil(handleFutureEvent): return
+
+    enableEventCallbacks()
+    handleFutureEvent = proc (e: Event) {.nimcall.} = 
+      futureMetrics.processEvent(e)

chronos/profiler/events.nim

@@ -1,3 +1,8 @@
+## 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.
+
 import ".."/timer
 import ".."/futures
 import ".."/srcloc
@@ -31,7 +36,8 @@ proc mkEvent(future: FutureBase, state: ExtendedFutureState): Event =
     timestamp: Moment.now(),
   )
   
-onFutureEvent = proc (future: FutureBase, state: FutureState): void {.nimcall.} =
+proc handleFutureEventCB*(future: FutureBase,
+    state: FutureState): void {.nimcall.} =
   {.cast(gcsafe).}:
     let extendedState = case state:
       of FutureState.Pending: ExtendedFutureState.Pending
@@ -42,7 +48,8 @@ onFutureEvent = proc (future: FutureBase, state: FutureState): void {.nimcall.}
     if not isNil(handleFutureEvent):
       handleFutureEvent(mkEvent(future, extendedState))
 
-onFutureExecEvent = proc (future: FutureBase, state: FutureExecutionState): void {.nimcall.} =
+proc handleFutureExecEventCB*(future: FutureBase,
+    state: FutureExecutionState): void {.nimcall.} =
   {.cast(gcsafe).}:
     let extendedState = case state:
       of FutureExecutionState.Running: ExtendedFutureState.Running

tests/config.nims

@@ -9,5 +9,4 @@ switch("threads", "on")
 switch("define", "nimRawSetjmp")
 
 ## REMOVE BEFORE MERGE!
---d:chronosFuturesInstrumentation
-# --d:chronosFutureTracking
+--d:chronosProfiling

tests/profiler/testevents.nim

@@ -3,7 +3,7 @@ import std/os
 import unittest2
 
 import ".."/".."/chronos
-import ".."/".."/chronos/profiler/[events, metrics]
+import ".."/".."/chronos/profiler
 
 import ./utils
 
@@ -53,11 +53,16 @@ suite "profiler hooks test suite":
 
   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")
@@ -73,8 +78,10 @@ suite "profiler hooks test suite":
       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"),
@@ -83,14 +90,17 @@ suite "profiler hooks test suite":
       # 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

tests/profiler/utils.nim

@@ -1,8 +1,5 @@
-import std/with
-
 import ".."/".."/chronos
-import ".."/".."/chronos/profiler/events
-import ".."/".."/chronos/profiler/metrics
+import ".."/".."/chronos/profiler
 
 type
   SimpleEvent* = object
@@ -26,7 +23,7 @@ proc recordEvent(event: Event) {.nimcall, gcsafe, raises: [].} =
       SimpleEvent(procedure: $event.location.procedure, state: event.newState))
 
     var timeShifted = event
-    timeshifted.timestamp = fakeTime
+    timeShifted.timestamp = fakeTime
 
     rawRecording.add(timeShifted)
 
@@ -43,6 +40,9 @@ proc clearRecording*(): void =
 
 proc installCallbacks*() =
   assert not installed, "Callbacks already installed"
+
+  enableEventCallbacks()
+
   oldHandleFutureEvent = handleFutureEvent
   handleFutureEvent = recordEvent
 

tests/testall.nim

@@ -8,7 +8,7 @@
 import testmacro, testsync, testsoon, testtime, testfut, testsignal,
        testaddress, testdatagram, teststream, testserver, testbugs, testnet,
        testasyncstream, testhttpserver, testshttpserver, testhttpclient,
-       testproc, testratelimit, testfutures, testthreadsync
+       testproc, testratelimit, testfutures, testthreadsync, testprofiler
 
 # Must be imported last to check for Pending futures
 import testutils

tests/testprofiler.nim

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

tests/testutils.nim

@@ -0,0 +1,87 @@
+#                Chronos Test Suite
+#            (c) Copyright 2020-Present
+#         Status Research & Development GmbH
+#
+#              Licensed under either of
+#  Apache License, version 2.0, (LICENSE-APACHEv2)
+#              MIT license (LICENSE-MIT)
+import unittest2
+import ../chronos, ../chronos/config
+
+{.used.}
+
+suite "Asynchronous utilities test suite":
+  when chronosFutureTracking:
+    proc getCount(): uint =
+      # This procedure counts number of Future[T] in double-linked list via list
+      # iteration.
+      var res = 0'u
+      for item in pendingFutures():
+        inc(res)
+      res
+
+  test "Future clean and leaks test":
+    when chronosFutureTracking:
+      if pendingFuturesCount(WithoutCompleted) == 0'u:
+        if pendingFuturesCount(OnlyCompleted) > 0'u:
+          poll()
+        check pendingFuturesCount() == 0'u
+      else:
+        echo dumpPendingFutures()
+        check false
+    else:
+      skip()
+
+  test "FutureList basics test":
+    when chronosFutureTracking:
+      var fut1 = newFuture[void]()
+      check:
+        getCount() == 1'u
+        pendingFuturesCount() == 1'u
+      var fut2 = newFuture[void]()
+      check:
+        getCount() == 2'u
+        pendingFuturesCount() == 2'u
+      var fut3 = newFuture[void]()
+      check:
+        getCount() == 3'u
+        pendingFuturesCount() == 3'u
+      fut1.complete()
+      poll()
+      check:
+        getCount() == 2'u
+        pendingFuturesCount() == 2'u
+      fut2.fail(newException(ValueError, ""))
+      poll()
+      check:
+        getCount() == 1'u
+        pendingFuturesCount() == 1'u
+      fut3.cancel()
+      poll()
+      check:
+        getCount() == 0'u
+        pendingFuturesCount() == 0'u
+    else:
+      skip()
+
+  test "FutureList async procedure test":
+    when chronosFutureTracking:
+      proc simpleProc() {.async.} =
+        await sleepAsync(10.milliseconds)
+
+      var fut = simpleProc()
+      check:
+        getCount() == 2'u
+        pendingFuturesCount() == 2'u
+
+      waitFor fut
+      check:
+        getCount() == 1'u
+        pendingFuturesCount() == 1'u
+
+      poll()
+      check:
+        getCount() == 0'u
+        pendingFuturesCount() == 0'u
+    else:
+      skip()