From 81711f8b11160cbef00b01120315ad5f849af780 Mon Sep 17 00:00:00 2001 From: gmega Date: Fri, 24 Nov 2023 19:32:41 -0300 Subject: [PATCH] add support for blocking children --- chronos/profiler/events.nim | 12 ++-- chronos/profiler/metrics.nim | 50 +++++++++++--- .../{testasyncprofiler.nim => testevents.nim} | 67 +------------------ tests/profiler/testmetrics.nim | 52 ++++++++++++++ tests/profiler/utils.nim | 1 + tests/testprofiler.nim | 4 ++ 6 files changed, 106 insertions(+), 80 deletions(-) rename tests/profiler/{testasyncprofiler.nim => testevents.nim} (69%) create mode 100644 tests/profiler/testmetrics.nim create mode 100644 tests/testprofiler.nim diff --git a/chronos/profiler/events.nim b/chronos/profiler/events.nim index 955401c..43bcc01 100644 --- a/chronos/profiler/events.nim +++ b/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(), ) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index b6adc21..463a4cd 100644 --- a/chronos/profiler/metrics.nim +++ b/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: diff --git a/tests/profiler/testasyncprofiler.nim b/tests/profiler/testevents.nim similarity index 69% rename from tests/profiler/testasyncprofiler.nim rename to tests/profiler/testevents.nim index 080be06..0251e07 100644 --- a/tests/profiler/testasyncprofiler.nim +++ b/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() \ No newline at end of file + ] \ No newline at end of file diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim new file mode 100644 index 0000000..1e80377 --- /dev/null +++ b/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 diff --git a/tests/profiler/utils.nim b/tests/profiler/utils.nim index f976376..96e4166 100644 --- a/tests/profiler/utils.nim +++ b/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" diff --git a/tests/testprofiler.nim b/tests/testprofiler.nim new file mode 100644 index 0000000..2dda14e --- /dev/null +++ b/tests/testprofiler.nim @@ -0,0 +1,4 @@ +import ./profiler/testevents +import ./profiler/testmetrics + +{.warning[UnusedImport]:off.}