nim-chroprof/tests/testprofiler.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