From 895b89166c0beee29b60154bde524f3ea50e43a2 Mon Sep 17 00:00:00 2001 From: gmega Date: Thu, 29 Feb 2024 17:55:45 -0300 Subject: [PATCH] initial import --- chroprof.nim | 6 + chroprof.nimble | 11 ++ chroprof/api.nim | 21 ++++ chroprof/events.nim | 62 ++++++++++ chroprof/profiler.nim | 167 +++++++++++++++++++++++++ config.nims | 1 + tests/testevents.nim | 132 ++++++++++++++++++++ tests/testprofiler.nim | 275 +++++++++++++++++++++++++++++++++++++++++ tests/utils.nim | 74 +++++++++++ 9 files changed, 749 insertions(+) create mode 100644 chroprof.nim create mode 100644 chroprof.nimble create mode 100644 chroprof/api.nim create mode 100644 chroprof/events.nim create mode 100644 chroprof/profiler.nim create mode 100644 config.nims create mode 100644 tests/testevents.nim create mode 100644 tests/testprofiler.nim create mode 100644 tests/utils.nim diff --git a/chroprof.nim b/chroprof.nim new file mode 100644 index 0000000..54e70a8 --- /dev/null +++ b/chroprof.nim @@ -0,0 +1,6 @@ +when not defined(chronosProfiling): + {.error: "chronprof requires -d:chronosProfiling to be enabled".} + +import ./chroprof/api + +export api \ No newline at end of file diff --git a/chroprof.nimble b/chroprof.nimble new file mode 100644 index 0000000..1c4e903 --- /dev/null +++ b/chroprof.nimble @@ -0,0 +1,11 @@ +mode = ScriptMode.Verbose + +packageName = "chroprof" +version = "0.1.0" +author = "Status Research & Development GmbH" +description = "A profiling tool for the Chronos networking framework" +license = "MIT or Apache License 2.0" +skipDirs = @["tests"] + +requires "nim >= 1.6.16", + "https://github.com/codex-storage/nim-chronos#feature/profiler-v4" \ No newline at end of file diff --git a/chroprof/api.nim b/chroprof/api.nim new file mode 100644 index 0000000..0529c21 --- /dev/null +++ b/chroprof/api.nim @@ -0,0 +1,21 @@ +import chronos/futures +import ./[profiler, events] + +type EventCallback = proc (e: Event) {.nimcall, gcsafe, raises: [].} + +var profilerInstance {.threadvar.}: ProfilerState + +proc getMetrics*(): MetricsTotals = + ## Returns the `MetricsTotals` for the event loop running in the + ## current thread. + result = profilerInstance.metrics + +proc enableEventCallbacks*(callback: EventCallback): void = + onBaseFutureEvent = handleBaseFutureEvent + onAsyncFutureEvent = handleAsyncFutureEvent + handleFutureEvent = callback + +proc enableProfiling*() = + ## Enables profiling for the the event loop running in the current thread. + handleFutureEvent = proc (e: Event) {.nimcall.} = + profilerInstance.processEvent(e) diff --git a/chroprof/events.nim b/chroprof/events.nim new file mode 100644 index 0000000..a2ecfe6 --- /dev/null +++ b/chroprof/events.nim @@ -0,0 +1,62 @@ +## This module provides the callbacks that hook into Chronos and record +## timestamped events on Future state transitions. It also consolidates +## the FutureState and AsyncFutureState into a single enum to ease downstream +## processing. +## +## This is an internal module and none of what is here should be considered API. + +import chronos/[timer, futures, srcloc] + +type + ExtendedFutureState* {.pure.} = enum + Pending, + Running, + Paused, + Completed, + Cancelled, + Failed, + + Event* = object + 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( + future: future, + newState: state, + timestamp: Moment.now(), + ) + +proc handleBaseFutureEvent*(future: FutureBase, + state: FutureState): void {.nimcall.} = + {.cast(gcsafe).}: + let extendedState = case state: + of FutureState.Pending: ExtendedFutureState.Pending + of FutureState.Completed: ExtendedFutureState.Completed + of FutureState.Cancelled: ExtendedFutureState.Cancelled + of FutureState.Failed: ExtendedFutureState.Failed + + if not isNil(handleFutureEvent): + handleFutureEvent(mkEvent(future, extendedState)) + +proc handleAsyncFutureEvent*(future: FutureBase, + state: AsyncFutureState): void {.nimcall.} = + {.cast(gcsafe).}: + let extendedState = case state: + of AsyncFutureState.Running: ExtendedFutureState.Running + of AsyncFutureState.Paused: ExtendedFutureState.Paused + + if not isNil(handleFutureEvent): + handleFutureEvent(mkEvent(future, extendedState)) + + + diff --git a/chroprof/profiler.nim b/chroprof/profiler.nim new file mode 100644 index 0000000..4201651 --- /dev/null +++ b/chroprof/profiler.nim @@ -0,0 +1,167 @@ +## This module contains the actual profiler implementation - the piece of code +## responsible for computing and aggregating metrics from timestamped event +## sequences. +## +import std/[tables, options, sets] +import chronos/[timer, srcloc] + +import ./events + +export timer, tables, sets, srcloc + +type + FutureType* = SrcLoc + ## Within the scope of the profiler, a source location identifies + ## a future type. + + AggregateMetrics* = object + ## Stores aggregate metrics for a given `FutureType`. + execTime*: Duration ## The total time that `Future`s of a given + ## `FutureType` actually ran; i.e., actively + ## occupied the event loop thread, summed + ## accross all such `Futures`. + + execTimeMax*: Duration ## The maximum time that a `Future` of a + ## given `FutureType` actually ran; i.e., + ## actively occupied the event loop thread. + + childrenExecTime*: Duration ## Total time that the children of `Future`s + ## of this `FutureType` actually ran; i.e., + ## actively occupied the event loop thread, + ## summed across all such children. + + wallClockTime*: Duration ## Total time that the Future was alive; + ## i.e., the time between the Future's + ## creation and its completion, summed + ## across all runs of this `FutureType`. + + stillbornCount*: uint ## Number of futures of this `FutureType` + ## that were born in a finished state; + ## i.e., a `FutureState` that is not Pending. + + callCount*: uint ## Total number of distinct `Future`s observed + ## for this `FutureType`. + + PartialMetrics* = object + state*: ExtendedFutureState + created*: Moment + lastStarted*: Moment + timeToFirstPause*: Duration + partialExecTime*: Duration + partialChildrenExecTime*: Duration + partialChildrenExecOverlap*: Duration + parent*: Option[uint] + pauses*: uint + + MetricsTotals* = Table[SrcLoc, AggregateMetrics] + + ProfilerState* = object + callStack: seq[uint] + partials: Table[uint, PartialMetrics] + metrics*: MetricsTotals + +proc `execTimeWithChildren`*(self: AggregateMetrics): Duration = + self.execTime + self.childrenExecTime + +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 `$`(location: SrcLoc): string = + $location.procedure & "[" & $location.file & ":" & $location.line & "]" + +proc futureCreated(self: var ProfilerState, event: Event): void = + assert not self.partials.hasKey(event.futureId), $event.location + + self.partials[event.futureId] = PartialMetrics( + created: event.timestamp, + state: Pending, + ) + +proc bindParent(self: var ProfilerState, metrics: ptr PartialMetrics): void = + let current = self.callStack.peek() + if current.isNone: + return + + if metrics.parent.isSome: + assert metrics.parent.get == current.get + metrics.parent = current + +proc futureRunning(self: var ProfilerState, event: Event): void = + assert self.partials.hasKey(event.futureId), $event.location + + self.partials.withValue(event.futureId, metrics): + assert metrics.state == Pending or metrics.state == Paused, + $event.location & " " & $metrics.state + + self.bindParent(metrics) + self.callStack.push(event.futureId) + + metrics.lastStarted = event.timestamp + metrics.state = Running + +proc futurePaused(self: var ProfilerState, event: Event): void = + 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 + + let segmentExecTime = event.timestamp - metrics.lastStarted + + if metrics.pauses == 0: + metrics.timeToFirstPause = segmentExecTime + metrics.partialExecTime += segmentExecTime + metrics.pauses += 1 + metrics.state = Paused + +proc futureCompleted(self: var ProfilerState, event: Event): void = + let location = event.location + if not self.metrics.hasKey(location): + self.metrics[location] = AggregateMetrics() + + self.metrics.withValue(location, aggMetrics): + if not self.partials.hasKey(event.futureId): + # Stillborn futures are those born in a finish state. We count those cause + # they may also be a byproduct of a bug. + aggMetrics.stillbornCount.inc() + return + + self.partials.withValue(event.futureId, metrics): + if metrics.state == Running: + self.futurePaused(event) + + 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 + + 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 ProfilerState, event: Event): void = + case event.newState: + of Pending: self.futureCreated(event) + of Running: self.futureRunning(event) + of Paused: self.futurePaused(event) + # Completion, failure and cancellation are currently handled the same way. + of Completed: self.futureCompleted(event) + of Failed: self.futureCompleted(event) + of Cancelled: self.futureCompleted(event) + +proc processAllEvents*(self: var ProfilerState, events: seq[Event]): void = + for event in events: + self.processEvent(event) \ No newline at end of file diff --git a/config.nims b/config.nims new file mode 100644 index 0000000..f2165a2 --- /dev/null +++ b/config.nims @@ -0,0 +1 @@ +--d:chronosProfiling \ No newline at end of file diff --git a/tests/testevents.nim b/tests/testevents.nim new file mode 100644 index 0000000..73505ec --- /dev/null +++ b/tests/testevents.nim @@ -0,0 +1,132 @@ +import std/os + +import chronos +import unittest2 + +import pkg/chroprof/events +import ./utils + +suite "Profiler hooks test suite": + + setup: + installCallbacks() + + teardown: + clearRecording() + revertCallbacks() + + test "should emit correct events for a simple future": + + proc simple() {.async.} = + os.sleep(1) + + waitFor simple() + + check recording == @[ + SimpleEvent(state: Pending, procedure: "simple"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "simple"), + SimpleEvent(state: Completed, procedure: "simple"), + ] + + test "should emit correct events 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() + + check recording == @[ + SimpleEvent(state: Pending, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 1"), + SimpleEvent(state: ExtendedFutureState.Pending, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: Paused, procedure: "withChildren"), + SimpleEvent(state: Completed, procedure: "chronos.sleepAsync(Duration)"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), + SimpleEvent(state: Completed, procedure: "withChildren"), + ] + + 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") + await child1() + recordSegment("segment 2") + + waitFor withChildren() + + check recording == @[ + # First iteration of parent and each child + SimpleEvent(state: Pending, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), + 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"), + SimpleEvent(state: ExtendedFutureState.Paused, procedure: "withChildren"), + + # 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 + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withChildren"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "segment 2"), + SimpleEvent(state: ExtendedFutureState.Completed, procedure: "withChildren"), + ] + + test "should not say a future is completed before children in finally blocks are run": + proc withFinally(): Future[void] {.async.} = + try: + return + finally: + recordSegment("segment 1") + await sleepAsync(10.milliseconds) + # both segments must run + recordSegment("segment 2") + + 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"), + ] \ No newline at end of file diff --git a/tests/testprofiler.nim b/tests/testprofiler.nim new file mode 100644 index 0000000..eafe90c --- /dev/null +++ b/tests/testprofiler.nim @@ -0,0 +1,275 @@ +import math +import sequtils +import unittest2 + +import chronos +import chroprof/profiler + +import ./utils + +suite "Profiler metrics test suite": + + setup: + installCallbacks() + + teardown: + clearRecording() + revertCallbacks() + resetTime() + + proc recordedMetrics(): MetricsTotals = + var profiler: ProfilerState + profiler.processAllEvents(rawRecording) + profiler.metrics + + test "should compute correct times for a simple blocking future": + proc simple() {.async.} = + advanceTime(50.milliseconds) + + waitFor simple() + + var metrics = recordedMetrics() + let simpleMetrics = metrics.forProc("simple") + + check simpleMetrics.execTime == 50.milliseconds + check simpleMetrics.wallClockTime == 50.milliseconds + + test "should compute correct times for a simple non-blocking future": + proc simple {.async.} = + advanceTime(10.milliseconds) + await advanceTimeAsync(50.milliseconds) + advanceTime(10.milliseconds) + + waitFor simple() + + var metrics = recordedMetrics() + let simpleMetrics = metrics.forProc("simple") + + check simpleMetrics.execTime == 20.milliseconds + check simpleMetrics.wallClockTime == 70.milliseconds + + test "should compute correct times for a non-blocking future with multiple pauses": + proc simple {.async.} = + advanceTime(10.milliseconds) + await advanceTimeAsync(50.milliseconds) + advanceTime(10.milliseconds) + await advanceTimeAsync(50.milliseconds) + advanceTime(10.milliseconds) + + waitFor simple() + + var metrics = recordedMetrics() + let simpleMetrics = metrics.forProc("simple") + + check simpleMetrics.execTime == 30.milliseconds + check simpleMetrics.wallClockTime == 130.milliseconds + + test "should compute correct times when there is a single blocking child": + proc child() {.async.} = + advanceTime(10.milliseconds) + + proc parent() {.async.} = + advanceTime(10.milliseconds) + await child() + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = recordedMetrics() + 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 + check childMetrics.childrenExecTime == ZeroDuration + + test "should compute correct times when there is a single non-blocking child": + proc child() {.async.} = + advanceTime(10.milliseconds) + await advanceTimeAsync(50.milliseconds) + advanceTime(10.milliseconds) + + proc parent() {.async.} = + advanceTime(10.milliseconds) + await child() + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = recordedMetrics() + let parentMetrics = metrics.forProc("parent") + let childMetrics = metrics.forProc("child") + + check parentMetrics.execTime == 20.milliseconds + check parentMetrics.childrenExecTime == 20.milliseconds + check parentMetrics.wallClockTime == 90.milliseconds + + check childMetrics.execTime == 20.milliseconds + check childMetrics.wallClockTime == 70.milliseconds + check childMetrics.childrenExecTime == ZeroDuration + + test "should compute correct times when there are multiple blocking and non-blocking children": + proc blockingChild() {.async.} = + advanceTime(10.milliseconds) + + proc nonblockingChild() {.async.} = + advanceTime(10.milliseconds) + await advanceTimeAsync(20.milliseconds) + advanceTime(10.milliseconds) + + proc parent() {.async.} = + advanceTime(10.milliseconds) + await blockingChild() + advanceTime(10.milliseconds) + await nonblockingChild() + advanceTime(10.milliseconds) + await blockingChild() + advanceTime(10.milliseconds) + await nonblockingChild() + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = recordedMetrics() + + let parentMetrics = metrics.forProc("parent") + let blockingChildMetrics = metrics.forProc("blockingChild") + let nonblockingChildMetrics = metrics.forProc("nonblockingChild") + + check parentMetrics.execTime == 50.milliseconds + check parentMetrics.childrenExecTime == 60.milliseconds + check parentMetrics.wallClockTime == 150.milliseconds + + check blockingChildMetrics.execTime == 20.milliseconds + check blockingChildMetrics.wallClockTime == 20.milliseconds + check blockingChildMetrics.childrenExecTime == ZeroDuration + + check nonblockingChildMetrics.execTime == 40.milliseconds + check nonblockingChildMetrics.wallClockTime == 80.milliseconds + check nonblockingChildMetrics.childrenExecTime == ZeroDuration + + test "should compute correct times when a child throws an exception": + proc child() {.async: (raises: [CatchableError]).} = + advanceTime(10.milliseconds) + raise newException(CatchableError, "child exception") + + proc parent() {.async: (raises: [CatchableError]).} = + advanceTime(10.milliseconds) + try: + await child() + except: + discard + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = recordedMetrics() + 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 + check childMetrics.childrenExecTime == ZeroDuration + + test "should compute correct times when a child gets cancelled": + proc child() {.async.} = + advanceTime(10.milliseconds) + await sleepAsync(1.hours) + + proc parent() {.async.} = + advanceTime(10.milliseconds) + # This is sort of subtle: we simulate that parent runs for 10 + # milliseconds before actually cancelling the child. This renders the + # test case less trivial as those 10 milliseconds should be billed as + # wallclock time at the child, causing the child's exec time and its + # wallclock time to differ. + let child = child() + advanceTime(10.milliseconds) + await child.cancelAndWait() + advanceTime(10.milliseconds) + + waitFor parent() + + var metrics = recordedMetrics() + let parentMetrics = metrics.forProc("parent") + let childMetrics = metrics.forProc("child") + + check parentMetrics.execTime == 30.milliseconds + check parentMetrics.childrenExecTime == 10.milliseconds + check parentMetrics.wallClockTime == 40.milliseconds + + check childMetrics.execTime == 10.milliseconds + check childMetrics.wallClockTime == 20.milliseconds + 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 + + test "should compute the correct execution time within finally blocks": + proc withFinally() {.async.} = + try: + advanceTime(10.milliseconds) + return + finally: + advanceTime(10.milliseconds) + await advanceTimeAsync(10.milliseconds) + advanceTime(10.milliseconds) + + waitFor withFinally() + + var metrics = recordedMetrics() + var withFinallyMetrics = metrics.forProc("withFinally") + + check withFinallyMetrics.execTime == 30.milliseconds + + test "should count futures which start in a completion state": + let completed {.used.} = Future.completed(42) + let failed {.used.} = Future[int].failed((ref ValueError)(msg: "msg")) + + var metrics = recordedMetrics() + + let stillborns = metrics.pairs.toSeq.map( + proc (item: (SrcLoc, AggregateMetrics)): uint = + item[1].stillbornCount).sum + + check stillborns == 2 \ No newline at end of file diff --git a/tests/utils.nim b/tests/utils.nim new file mode 100644 index 0000000..2899dac --- /dev/null +++ b/tests/utils.nim @@ -0,0 +1,74 @@ +import chronos +import pkg/chroprof/[api, events, profiler] + +type + SimpleEvent* = object + procedure*: string + state*: ExtendedFutureState + +# XXX this is sort of bad cause we get global state all over, but the fact we +# can't use closures on callbacks and that callbacks themselves are just +# global vars means we can't really do much better for now. +var recording*: seq[SimpleEvent] +var rawRecording*: seq[Event] +var fakeTime*: Moment = Moment.now() + +proc recordEvent(event: Event) {.nimcall, gcsafe, raises: [].} = + {.cast(gcsafe).}: + recording.add( + SimpleEvent(procedure: $event.location.procedure, state: event.newState)) + + var timeShifted = event + timeShifted.timestamp = fakeTime + + rawRecording.add(timeShifted) + +proc recordSegment*(segment: string) = + {.cast(gcsafe).}: + recording.add(SimpleEvent( + procedure: segment, + state: ExtendedFutureState.Running + )) + +proc clearRecording*(): void = + recording = @[] + rawRecording = @[] + +proc installCallbacks*() = + assert isNil(handleFutureEvent), "There is a callback already installed" + + enableEventCallbacks(recordEvent) + +proc revertCallbacks*() = + assert not isNil(handleFutureEvent), "There are no callbacks installed" + + handleFutureEvent = nil + +proc forProc*(self: var MetricsTotals, procedure: string): AggregateMetrics = + for (key, aggMetrics) in self.mpairs: + if key.procedure == procedure: + return aggMetrics + +proc resetTime*() = + fakeTime = Moment.now() + +proc advanceTime*(duration: Duration) = + fakeTime += duration + +proc advanceTimeAsync*(duration: Duration): Future[void] = + # Simulates a non-blocking operation that takes the provided duration to + # complete. + var retFuture = newFuture[void]("advanceTimeAsync") + var timer: TimerCallback + + proc completion(data: pointer) {.gcsafe.} = + if not(retFuture.finished()): + advanceTime(duration) + retFuture.complete() + + # The actual value for the timer is irrelevant, the important thing is that + # this causes the parent to pause before we advance time. + timer = setTimer(Moment.fromNow(10.milliseconds), + completion, cast[pointer](retFuture)) + + return retFuture