mirror of
https://github.com/logos-storage/nim-chroprof.git
synced 2026-01-02 13:33:06 +00:00
337 lines
10 KiB
Nim
337 lines
10 KiB
Nim
import std/math
|
|
import std/sequtils
|
|
|
|
import unittest2
|
|
import chronos
|
|
|
|
import ../chroprof/profiler
|
|
|
|
import ./utils
|
|
|
|
suite "profiler metrics":
|
|
setup:
|
|
startRecording()
|
|
|
|
teardown:
|
|
stopRecording()
|
|
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
|
|
|
|
test "should properly account for children's execution time even when those finish after the parent":
|
|
let barrier = newFuture[void]("barrier")
|
|
|
|
proc child() {.async.} =
|
|
await barrier
|
|
advanceTime(10.milliseconds)
|
|
|
|
proc parent(): Future[seq[Future[void]]] {.async.} =
|
|
advanceTime(10.milliseconds)
|
|
return @[child(), child()]
|
|
|
|
let childFut = waitFor parent()
|
|
barrier.complete()
|
|
waitFor allFutures(childFut)
|
|
|
|
var metrics = recordedMetrics()
|
|
let parentMetrics = metrics.forProc("parent")
|
|
let childMetrics = metrics.forProc("child")
|
|
|
|
check parentMetrics.execTime == 10.milliseconds
|
|
check parentMetrics.childrenExecTime == 20.milliseconds
|
|
check parentMetrics.wallClockTime == 10.milliseconds
|
|
|
|
check childMetrics.execTime == 20.milliseconds
|
|
check childMetrics.wallClockTime == 30.milliseconds
|
|
check childMetrics.childrenExecTime == ZeroDuration
|
|
|
|
test "should aggregate child execution times across nested children":
|
|
proc child() {.async.} =
|
|
advanceTime(10.milliseconds)
|
|
|
|
proc parent() {.async.} =
|
|
advanceTime(10.milliseconds)
|
|
await child()
|
|
advanceTime(10.milliseconds)
|
|
|
|
proc grandparent() {.async.} =
|
|
advanceTime(10.milliseconds)
|
|
await parent()
|
|
advanceTime(10.milliseconds)
|
|
|
|
waitFor grandparent()
|
|
|
|
var metrics = recordedMetrics()
|
|
let grandparentMetrics = metrics.forProc("grandparent")
|
|
let parentMetrics = metrics.forProc("parent")
|
|
let childMetrics = metrics.forProc("child")
|
|
|
|
check grandparentMetrics.execTime == 20.milliseconds
|
|
check grandparentMetrics.childrenExecTime == 30.milliseconds
|
|
check grandparentMetrics.wallClockTime == 50.milliseconds
|
|
|
|
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
|