remove profiler from Chronos, keep only instrumentation code

This commit is contained in:
gmega 2024-03-01 09:39:12 -03:00
parent a68de9fe17
commit c8899eb134
No known key found for this signature in database
GPG Key ID: FFD8DAF00660270F
8 changed files with 2 additions and 734 deletions

View File

@ -1,28 +0,0 @@
import ./config
when chronosProfiling:
import futures
import ./profiler/[events, metrics]
export futures, events, metrics
when not chronosFutureId:
{.error: "chronosProfiling requires chronosFutureId to be enabled".}
var futureMetrics {.threadvar.}: ProfilerMetrics
proc getMetrics*(): ProfilerMetrics =
## Returns metrics for the current event loop.
result = futureMetrics
proc enableEventCallbacks*(): void =
onBaseFutureEvent = handleBaseFutureEvent
onAsyncFutureEvent = handleAsyncFutureEvent
proc enableProfiling*() =
## Enables profiling on the current event loop.
if not isNil(handleFutureEvent): return
enableEventCallbacks()
handleFutureEvent = proc (e: Event) {.nimcall.} =
futureMetrics.processEvent(e)

View File

@ -1,61 +0,0 @@
## This module defines the lower-level callback implementations that hook into
## the Chronos scheduler when profiling is enabled. The main goal is to provide
## timestamped state changes for futures, which form the input for the profiler.
import ../timer
import ../futures
import ../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))

View File

@ -1,141 +0,0 @@
import std/tables
import std/options
import std/sets
import ./events
import ../[timer, srcloc]
export timer, tables, sets, srcloc
type
AggregateFutureMetrics* = object
execTime*: Duration
execTimeMax*: Duration
childrenExecTime*: Duration
wallClockTime*: Duration
stillbornCount*: uint
callCount*: uint
RunningFuture* = object
state*: ExtendedFutureState
created*: Moment
lastStarted*: Moment
timeToFirstPause*: Duration
partialExecTime*: Duration
partialChildrenExecTime*: Duration
partialChildrenExecOverlap*: Duration
parent*: Option[uint]
pauses*: uint
MetricsTotals* = Table[SrcLoc, AggregateFutureMetrics]
ProfilerMetrics* = object
callStack: seq[uint]
partials: Table[uint, RunningFuture]
totals*: MetricsTotals
proc `execTimeWithChildren`*(self: AggregateFutureMetrics): 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 ProfilerMetrics, event: Event): void =
assert not self.partials.hasKey(event.futureId), $event.location
self.partials[event.futureId] = RunningFuture(
created: event.timestamp,
state: Pending,
)
proc bindParent(self: var ProfilerMetrics, metrics: ptr RunningFuture): 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 ProfilerMetrics, 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 ProfilerMetrics, 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 ProfilerMetrics, event: Event): void =
let location = event.location
if not self.totals.hasKey(location):
self.totals[location] = AggregateFutureMetrics()
self.totals.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 ProfilerMetrics, 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 ProfilerMetrics, events: seq[Event]): void =
for event in events:
self.processEvent(event)

View File

@ -1,133 +0,0 @@
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":
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"),
]

View File

@ -1,273 +0,0 @@
import math
import sequtils
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: (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.totals.pairs.toSeq.map(
proc (item: (SrcLoc, AggregateFutureMetrics)): uint =
item[1].stillbornCount).sum
check stillborns == 2

View File

@ -1,84 +0,0 @@
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

View File

@ -11,7 +11,7 @@ when (chronosEventEngine in ["epoll", "kqueue"]) or defined(windows):
import testmacro, testsync, testsoon, testtime, testfut, testsignal,
testaddress, testdatagram, teststream, testserver, testbugs, testnet,
testasyncstream, testhttpserver, testshttpserver, testhttpclient,
testproc, testratelimit, testfutures, testthreadsync, testprofiler
testproc, testratelimit, testfutures, testthreadsync
# Must be imported last to check for Pending futures
import testutils
@ -20,7 +20,7 @@ elif chronosEventEngine == "poll":
import testmacro, testsync, testsoon, testtime, testfut, testaddress,
testdatagram, teststream, testserver, testbugs, testnet,
testasyncstream, testhttpserver, testshttpserver, testhttpclient,
testratelimit, testfutures, testthreadsync, testprofiler
testratelimit, testfutures, testthreadsync
# Must be imported last to check for Pending futures
import testutils

View File

@ -1,12 +0,0 @@
import ../chronos/config
when chronosProfiling:
import ../chronos/profiler
import ./profiler/testevents
import ./profiler/testmetrics
enableProfiling()
{.used.}
{.warning[UnusedImport]:off.}