add call count and max exec time; rename enable => enableProfiling to clear up intent

chronos/profiler.nim

@@ -6,8 +6,8 @@ when chronosProfiling:
 
   export futures, events, metrics
 
-  when not defined(chronosFutureId):
-    {.error "chronosProfiling requires chronosFutureId to be enabled".}
+  when not chronosFutureId:
+    {.error: "chronosProfiling requires chronosFutureId to be enabled".}
 
   var futureMetrics {.threadvar.}: ProfilerMetrics 
 
@@ -19,7 +19,7 @@ when chronosProfiling:
     onFutureEvent = handleFutureEventCB
     onFutureExecEvent = handleFutureExecEventCB
     
-  proc enable*() = 
+  proc enableProfiling*() =
     ## Enables profiling on the current event loop.
     if not isNil(handleFutureEvent): return
 

chronos/profiler/metrics.nim

@@ -9,8 +9,10 @@ export timer, tables, srcloc
 type
   AggregateFutureMetrics* = object
     execTime*: Duration
+    execTimeMax*: Duration
     childrenExecTime*: Duration
     wallClockTime*: Duration
+    callCount*: uint
 
   RunningFuture* = object
     state*: ExtendedFutureState
@@ -92,7 +94,11 @@ proc futureCompleted(self: var ProfilerMetrics, event: Event): void =
       self.totals[location] = AggregateFutureMetrics()
 
     self.totals.withValue(location, aggMetrics):
-      aggMetrics.execTime += metrics.partialExecTime - metrics.partialChildrenExecOverlap
+      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
 

tests/profiler/testmetrics.nim

@@ -204,4 +204,39 @@ suite "profiler metrics test suite":
 
       check childMetrics.execTime == 10.milliseconds
       check childMetrics.wallClockTime == 20.milliseconds
-      check childMetrics.childrenExecTime == ZeroDuration
+      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