From 651f3d62a5b9adb7576435ea7c8c475161fb2672 Mon Sep 17 00:00:00 2001 From: Jaremy Creechley Date: Tue, 28 Nov 2023 22:36:58 -0700 Subject: [PATCH] import tests --- tests/profiler/example.nim | 18 +++ tests/profiler/testevents.nim | 134 ++++++++++++++++++ tests/profiler/testmetrics.nim | 242 +++++++++++++++++++++++++++++++++ tests/profiler/utils.nim | 84 ++++++++++++ tests/testprofiler.nim | 10 ++ 5 files changed, 488 insertions(+) create mode 100644 tests/profiler/example.nim create mode 100644 tests/profiler/testevents.nim create mode 100644 tests/profiler/testmetrics.nim create mode 100644 tests/profiler/utils.nim create mode 100644 tests/testprofiler.nim diff --git a/tests/profiler/example.nim b/tests/profiler/example.nim new file mode 100644 index 0000000..6725ee8 --- /dev/null +++ b/tests/profiler/example.nim @@ -0,0 +1,18 @@ +import os +import ../../chronos + +proc child11() {.async.} = + echo "I ran" + await sleepAsync(10.milliseconds) + +proc child2() {.async.} = + os.sleep(10) + +proc child1() {.async.} = + await child2() + await child11() + +proc p() {.async.} = + echo "r1" + await child1() + echo "r2" \ No newline at end of file diff --git a/tests/profiler/testevents.nim b/tests/profiler/testevents.nim new file mode 100644 index 0000000..86c21f7 --- /dev/null +++ b/tests/profiler/testevents.nim @@ -0,0 +1,134 @@ +import std/os + +import unittest2 + +import ".."/".."/chronos +import ".."/".."/chronos/profiler + +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": + skip() + when false: + # TODO: chronos allows completed futures to generate children in their + # finally blocks. This causes a set of transitions that break our state + # machine. + proc withFinally(): Future[void] {.async.} = + try: + return + finally: + await sleepAsync(10.milliseconds) + + waitFor withFinally() + + check recording == @[ + SimpleEvent(state: Pending, procedure: "withFinally"), + SimpleEvent(state: ExtendedFutureState.Running, procedure: "withFinally"), + 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.Completed, procedure: "withFinally") + ] diff --git a/tests/profiler/testmetrics.nim b/tests/profiler/testmetrics.nim new file mode 100644 index 0000000..348914e --- /dev/null +++ b/tests/profiler/testmetrics.nim @@ -0,0 +1,242 @@ +import unittest2 + +import ".."/".."/chronos +import ".."/".."/chronos/profiler/metrics + +import ./utils + +suite "profiler metrics test suite": + + setup: + installCallbacks() + + teardown: + clearRecording() + revertCallbacks() + resetTime() + + proc recordedMetrics(): ProfilerMetrics = + result.processAllEvents(rawRecording) + + 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.} = + 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 + + 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 \ No newline at end of file diff --git a/tests/profiler/utils.nim b/tests/profiler/utils.nim new file mode 100644 index 0000000..966a875 --- /dev/null +++ b/tests/profiler/utils.nim @@ -0,0 +1,84 @@ +import ".."/".."/chronos +import ".."/".."/chronos/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() + +# FIXME bad, this needs to be refactored into a callback interface for the profiler. +var oldHandleFutureEvent: proc(event: Event) {.nimcall, gcsafe, raises: [].} = nil +var installed: bool = false + +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 not installed, "Callbacks already installed" + + enableEventCallbacks() + + oldHandleFutureEvent = handleFutureEvent + handleFutureEvent = recordEvent + + installed = true + +proc revertCallbacks*() = + assert installed, "Callbacks already uninstalled" + + handleFutureEvent = oldHandleFutureEvent + installed = false + +proc forProc*(self: var ProfilerMetrics, procedure: string): AggregateFutureMetrics = + for (key, aggMetrics) in self.totals.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 diff --git a/tests/testprofiler.nim b/tests/testprofiler.nim new file mode 100644 index 0000000..e5b1a10 --- /dev/null +++ b/tests/testprofiler.nim @@ -0,0 +1,10 @@ +import ../chronos/config + +when chronosProfiling: + import ../chronos/profiler + + import ./profiler/testevents + import ./profiler/testmetrics + +{.used.} +{.warning[UnusedImport]:off.}