From e65c48c153433d968b47f1c405e458d3449728e8 Mon Sep 17 00:00:00 2001 From: gmega Date: Mon, 27 Nov 2023 10:58:07 -0300 Subject: [PATCH] add tests for exceptions, cancellation, and multiple pauses --- chronos/profiler/metrics.nim | 5 +- tests/profiler/testmetrics.nim | 118 ++++++++++++++++++++++++++++++++- 2 files changed, 120 insertions(+), 3 deletions(-) diff --git a/chronos/profiler/metrics.nim b/chronos/profiler/metrics.nim index 463a4cd..bf5dca8 100644 --- a/chronos/profiler/metrics.nim +++ b/chronos/profiler/metrics.nim @@ -108,9 +108,10 @@ proc processEvent*(self: var ProfilerMetrics, event: Event): void = 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) - else: - assert false, "Unimplemented" + of Failed: self.futureCompleted(event) + of Cancelled: self.futureCompleted(event) proc processAllEvents*(self: var ProfilerMetrics, events: seq[Event]): void = for event in events: diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim index a2c3dbc..4ccc809 100644 --- a/tests/profiler/testmetrics.nim +++ b/tests/profiler/testmetrics.nim @@ -44,7 +44,23 @@ suite "profiler metrics test suite": check simpleMetrics.execTime == 20.milliseconds check simpleMetrics.wallClockTime == 70.milliseconds - test "should compute correct times whent there is a single blocking child": + 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) @@ -65,6 +81,7 @@ suite "profiler metrics test suite": 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.} = @@ -89,3 +106,102 @@ suite "profiler metrics test suite": 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.} = + advanceTime(10.milliseconds) + raise newException(Exception, "child exception") + + proc parent() {.async.} = + 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 \ No newline at end of file