add support for blocking children

chronos/profiler/events.nim

@@ -12,17 +12,21 @@ type
     Failed,
 
   Event* = object
-    futureId*: uint
-    location*: SrcLoc
+    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(
-    futureId: future.id,
-    location: future.internalLocation[Create][],
+    future: future,
     newState: state,
     timestamp: Moment.now(),
   )

chronos/profiler/metrics.nim

@@ -1,4 +1,5 @@
 import std/tables
+import std/options
 
 import ./events
 import ../[timer, srcloc]
@@ -6,8 +7,6 @@ import ../[timer, srcloc]
 export timer, tables, srcloc
 
 type
-  Clock* = proc (): Moment
-
   AggregateFutureMetrics* = object
     execTime*: Duration
     childrenExecTime*: Duration
@@ -19,16 +18,25 @@ type
     lastStarted*: Moment
     timeToFirstPause*: Duration
     partialExecTime*: Duration
+    partialChildrenExecTime*: Duration
+    partialChildrenExecOverlap*: Duration
+    parent*: Option[uint]
     pauses*: uint
-    
+
   ProfilerMetrics* = object
+    running: seq[uint]
     partials: Table[uint, RunningFuture]
     totals*: Table[SrcLoc, AggregateFutureMetrics]
 
-proc init*(T: typedesc[ProfilerMetrics]): ProfilerMetrics =
-  result.clock = timer.now
-  result.partials = initTable[uint, RunningFuture]()
-  result.totals = initTable[SrcLoc, AggregateFutureMetrics]()
+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 futureCreated(self: var ProfilerMetrics, event: Event): void =
   assert not self.partials.hasKey(event.futureId)
@@ -38,22 +46,36 @@ proc futureCreated(self: var ProfilerMetrics, event: Event): void =
     state: Pending,
   )
 
+proc bindParent(self: var ProfilerMetrics, metrics: ptr RunningFuture): void =
+  let current = self.running.peek()
+  if current.isNone:
+    return
+
+  if metrics.parent.isSome:
+    assert metrics.parent.get == current.get
+  metrics.parent = current
+
 proc futureRunning(self: var ProfilerMetrics, event: Event): void = 
   assert self.partials.hasKey(event.futureId)
 
   self.partials.withValue(event.futureId, metrics):
     assert metrics.state == Pending or metrics.state == Paused
 
+    self.bindParent(metrics)
+    self.running.push(event.futureId)
+
     metrics.lastStarted = event.timestamp
     metrics.state = Running
 
 proc futurePaused(self: var ProfilerMetrics, event: Event): void = 
   assert self.partials.hasKey(event.futureId)
+  assert event.futureId == self.running.pop()
 
   self.partials.withValue(event.futureId, metrics):
     assert metrics.state == Running
 
     let segmentExecTime = event.timestamp - metrics.lastStarted
+
     if metrics.pauses == 0:
       metrics.timeToFirstPause = segmentExecTime
     metrics.partialExecTime += segmentExecTime
@@ -68,12 +90,18 @@ proc futureCompleted(self: var ProfilerMetrics, event: Event): void =
     let location = event.location
     if not self.totals.hasKey(location):
       self.totals[location] = AggregateFutureMetrics()
-  
+
     self.totals.withValue(location, aggMetrics):
-      aggMetrics.execTime += metrics.partialExecTime
+      aggMetrics.execTime += metrics.partialExecTime - metrics.partialChildrenExecOverlap
+      aggMetrics.childrenExecTime += metrics.partialChildrenExecTime
       aggMetrics.wallClockTime += event.timestamp - metrics.created
-    
-  self.partials.del(event.futureId)
+
+    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 ProfilerMetrics, event: Event): void =
   case event.newState:

tests/profiler/testevents.nim

@@ -14,7 +14,7 @@ suite "profiler hooks test suite":
 
   teardown:
     clearRecording()
-    revertCallbacks()
+    revertCallbacks() 
 
   test "should emit correct events for a simple future":
     
@@ -97,67 +97,4 @@ suite "profiler hooks test suite":
       SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"),
       SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"),
       SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withChildren"),
-    ]
-
-
-suite "profiler metrics test suite":
-  
-    setup:
-      installCallbacks()
-
-    teardown:
-      clearRecording()
-      revertCallbacks()
-      resetTime()
-  
-    test "should compute correct times for a simple future":
-
-      var metrics = ProfilerMetrics()
-
-      proc simple() {.async.} =
-        advanceTime(50.milliseconds)
-        
-      waitFor simple()
-
-      metrics.processAllEvents(rawRecording)
-
-      let simpleMetrics = metrics.forProc("simple")
-      
-      check simpleMetrics.execTime == 50.milliseconds
-      check simpleMetrics.wallClockTime == 50.milliseconds
-
-
-    # test "should compute correct times when a single child runs as part of the parent":
-
-    #   var metrics = ProfilerMetrics()
-
-    #   proc child1() {.async.} = 
-    #     advanceTime(10.milliseconds)
-
-    #   proc withChildren() {.async.} =
-    #     advanceTime(10.milliseconds)
-    #     await child1()
-    #     advanceTime(10.milliseconds)
-        
-    #   waitFor withChildren()
-
-    #   metrics.processAllEvents(rawRecording)
-     
-    #   let withChildrenMetrics = metrics.forProc("withChildren")
-    #   let child1Metrics = metrics.forProc("child1")
-
-    #   check withChildrenMetrics.execTime == 20.milliseconds
-    #   check withChildrenMetrics.childrenExecTime == 10.milliseconds
-    #   check withChildrenMetrics.wallClockTime == 30.milliseconds
-
-    #   check child1Metrics.execTime == 10.milliseconds
-    #   check child1Metrics.wallClockTime == 10.milliseconds 
-  
-#     # test "should emit correct metrics 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()
+    ]

tests/profiler/testmetrics.nim

@@ -0,0 +1,52 @@
+import unittest2
+
+import ".."/".."/chronos
+import ".."/".."/chronos/profiler/metrics
+
+import ./utils
+
+suite "profiler metrics test suite":
+  
+    setup:
+      installCallbacks()
+
+    teardown:
+      clearRecording()
+      revertCallbacks()
+      resetTime()
+  
+    test "should compute correct times for a simple future":
+      proc simple() {.async.} =
+        advanceTime(50.milliseconds)
+        
+      waitFor simple()
+
+      var metrics = ProfilerMetrics()
+      metrics.processAllEvents(rawRecording)
+      let simpleMetrics = metrics.forProc("simple")
+      
+      check simpleMetrics.execTime == 50.milliseconds
+      check simpleMetrics.wallClockTime == 50.milliseconds
+
+    test "should compute correct times for blocking children":
+      proc child() {.async.} = 
+        advanceTime(10.milliseconds)
+
+      proc parent() {.async.} =
+        advanceTime(10.milliseconds)
+        await child()
+        advanceTime(10.milliseconds)
+        
+      waitFor parent()
+
+      var metrics = ProfilerMetrics()
+      metrics.processAllEvents(rawRecording)
+      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

tests/profiler/utils.nim

@@ -39,6 +39,7 @@ proc recordSegment*(segment: string) =
 
 proc clearRecording*(): void =
   recording = @[]
+  rawRecording = @[]
 
 proc installCallbacks*() =
   assert not installed, "Callbacks already installed"

tests/testprofiler.nim

@@ -0,0 +1,4 @@
+import ./profiler/testevents
+import ./profiler/testmetrics
+
+{.warning[UnusedImport]:off.}