logos-storage/nim-chroprof
1
0
Fork 0
mirror of https://github.com/logos-storage/nim-chroprof.git synced 2026-01-02 13:33:06 +00:00
Code Issues Packages Projects Releases Wiki Activity

run nph

Browse Source
This commit is contained in:
gmega 2024-03-01 13:44:06 -03:00
parent 13d7b384b7
commit b972187054
No known key found for this signature in database
GPG Key ID: FFD8DAF00660270F
11 changed files with 515 additions and 479 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
chroprof.nim
View File

@ -3,4 +3,4 @@ when not defined(chronosProfiling):
import ./chroprof/api
export api
export api

15
chroprof.nimble
View File

@ -1,17 +1,16 @@
mode = ScriptMode.Verbose
packageName = "chroprof"
version = "0.1.0"
author = "Status Research & Development GmbH"
version = "0.1.0"
author = "Status Research & Development GmbH"
description = "A profiling tool for the Chronos networking framework"
license = "MIT or Apache License 2.0"
skipDirs = @["tests"]
license = "MIT or Apache License 2.0"
skipDirs = @["tests"]
requires "nim >= 1.6.16",
"https://github.com/codex-storage/nim-chronos#feature/profiler-v4",
"metrics >= 0.1.0"
requires "nim >= 1.6.16",
"https://github.com/codex-storage/nim-chronos#feature/profiler-v4", "metrics >= 0.1.0"
task test, "Run tests":
exec "nim c --out:./build/testall -r tests/testall.nim"
# nim-metrics doesn't play well with ARC
exec "nim c --out:./build/testall --mm:refc -d:metrics -r tests/testall.nim"
exec "nim c --out:./build/testall --mm:refc -d:metrics -r tests/testall.nim"

9
chroprof/api.nim
View File

@ -1,11 +1,12 @@
import ./[profiler, events]
export Event, ExtendedFutureState, ProfilerState, MetricsTotals,
AggregateMetrics, FutureType, execTimeWithChildren
export
Event, ExtendedFutureState, ProfilerState, MetricsTotals, AggregateMetrics,
FutureType, execTimeWithChildren
var profilerInstance {.threadvar.}: ProfilerState
proc getMetrics*(): MetricsTotals =
proc getMetrics*(): MetricsTotals =
## Returns the `MetricsTotals` for the event loop running in the
## current thread.
result = profilerInstance.metrics
@ -19,7 +20,7 @@ proc enableProfiling*(callback: EventCallback = nil) =
proc(e: Event) {.nimcall.} =
profilerInstance.processEvent(e)
else:
proc (e: Event) {.nimcall.} =
proc(e: Event) {.nimcall.} =
profilerInstance.processEvent(e)
callback(e)
)

119
chroprof/collector.nim
View File

@ -23,9 +23,9 @@ when defined(metrics):
lastSample: Time
collections*: uint
MetricsSampler = proc (): MetricsTotals {.raises: [].}
MetricsSampler = proc(): MetricsTotals {.raises: [].}
Clock = proc (): Time {.raises: [].}
Clock = proc(): Time {.raises: [].}
FutureMetrics = (FutureType, AggregateMetrics)
@ -39,15 +39,15 @@ when defined(metrics):
declarePublicGauge(
chronos_exec_time_with_children_total,
"chronos_exec_time_with_children_total of this proc plus of all" &
"its children (procs that this proc called and awaited for)",
"chronos_exec_time_with_children_total of this proc plus of all" &
"its children (procs that this proc called and awaited for)",
labels = locationLabels,
)
declarePublicGauge(
chronos_wall_time_total,
"the amount of time elapsed from when the async proc was started to when" &
"it completed",
"it completed",
labels = locationLabels,
)
@ -64,7 +64,7 @@ when defined(metrics):
labels = locationLabels,
)
proc threadId(): int =
proc threadId(): int =
when defined(getThreadId):
getThreadId()
else:
@ -75,82 +75,82 @@ when defined(metrics):
let moduleInitThread = threadId()
proc newCollector*(
ChronosProfilerInfo: typedesc,
sampler: MetricsSampler,
clock: Clock,
sampleInterval: times.Duration,
k: int = 10,
): ChronosProfilerInfo = ChronosProfilerInfo(
sampler: sampler,
clock: clock,
k: k,
sampleInterval: sampleInterval,
init: true,
lastSample: low(Time),
)
ChronosProfilerInfo: typedesc,
sampler: MetricsSampler,
clock: Clock,
sampleInterval: times.Duration,
k: int = 10,
): ChronosProfilerInfo =
ChronosProfilerInfo(
sampler: sampler,
clock: clock,
k: k,
sampleInterval: sampleInterval,
init: true,
lastSample: low(Time),
)
proc collectSlowestProcs(
self: ChronosProfilerInfo,
profilerMetrics: seq[FutureMetrics],
timestampMillis: int64,
k: int,
self: ChronosProfilerInfo,
profilerMetrics: seq[FutureMetrics],
timestampMillis: int64,
k: int,
): void =
for (i, pair) in enumerate(profilerMetrics):
if i == k:
break
let (location, metrics) = pair
let locationLabels = @[
$(location.procedure),
$(location.file),
$(location.line),
]
let locationLabels = @[$(location.procedure), $(location.file), $(location.line)]
chronos_exec_time_total.set(metrics.execTime.nanoseconds,
labelValues = locationLabels)
chronos_exec_time_with_children_total.set(
metrics.execTimeWithChildren.nanoseconds,
labelValues = locationLabels
chronos_exec_time_total.set(
metrics.execTime.nanoseconds, labelValues = locationLabels
)
chronos_wall_time_total.set(metrics.wallClockTime.nanoseconds,
labelValues = locationLabels)
chronos_exec_time_with_children_total.set(
metrics.execTimeWithChildren.nanoseconds, labelValues = locationLabels
)
chronos_single_exec_time_max.set(metrics.execTimeMax.nanoseconds,
labelValues = locationLabels)
chronos_wall_time_total.set(
metrics.wallClockTime.nanoseconds, labelValues = locationLabels
)
chronos_call_count_total.set(metrics.callCount.int64,
labelValues = locationLabels)
chronos_single_exec_time_max.set(
metrics.execTimeMax.nanoseconds, labelValues = locationLabels
)
chronos_call_count_total.set(
metrics.callCount.int64, labelValues = locationLabels
)
proc collect*(self: ChronosProfilerInfo, force: bool = false): void =
# Calling this method from the wrong thread has happened a lot in the past,
# so this makes sure we're not doing anything funny.
assert threadId() == moduleInitThread, "You cannot call collect() from" &
" a thread other than the one that initialized the metricscolletor module"
assert threadId() == moduleInitThread,
"You cannot call collect() from" &
" a thread other than the one that initialized the metricscolletor module"
let now = self.clock()
if not force and (now - self.lastSample < self.sampleInterval):
return
self.collections += 1
var currentMetrics = self.
sampler().
pairs.
toSeq.
var currentMetrics = self
.sampler().pairs.toSeq
.
# We don't scoop metrics with 0 exec time as we have a limited number of
# prometheus slots, and those are less likely to be useful in debugging
# Chronos performance issues.
filter(
proc (pair: FutureMetrics): bool =
proc(pair: FutureMetrics): bool =
pair[1].execTimeWithChildren.nanoseconds > 0
).
sorted(
proc (a, b: FutureMetrics): int =
cmp(a[1].execTimeWithChildren, b[1].execTimeWithChildren),
order = SortOrder.Descending
)
.sorted(
proc(a, b: FutureMetrics): int =
cmp(a[1].execTimeWithChildren, b[1].execTimeWithChildren)
,
order = SortOrder.Descending,
)
self.collectSlowestProcs(currentMetrics, now.toMilliseconds(), self.k)
@ -174,22 +174,23 @@ when defined(metrics):
var asyncProfilerInfo* {.global.}: ChronosProfilerInfo
proc enableProfilerMetrics*(k: int) =
assert threadId() == moduleInitThread,
"You cannot call enableProfilerMetrics() from a thread other than" &
" the one that initialized the metricscolletor module."
assert threadId() == moduleInitThread,
"You cannot call enableProfilerMetrics() from a thread other than" &
" the one that initialized the metricscolletor module."
asyncProfilerInfo = ChronosProfilerInfo.newCollector(
sampler = getMetrics,
k = k,
# We want to collect metrics every 5 seconds.
sampleInterval = initDuration(seconds = 5),
clock = proc (): Time = getTime(),
clock = proc(): Time =
getTime()
,
)
enableProfiling(
proc (e: Event) {.nimcall, gcsafe, raises: [].} =
proc(e: Event) {.nimcall, gcsafe, raises: [].} =
{.cast(gcsafe).}:
if e.newState == ExtendedFutureState.Completed:
asyncProfilerInfo.collect()
)

42
chroprof/events.nim
View File

@ -9,21 +9,20 @@ import chronos/[timer, futures, srcloc]
type
ExtendedFutureState* {.pure.} = enum
Pending,
Running,
Paused,
Completed,
Cancelled,
Failed,
Pending
Running
Paused
Completed
Cancelled
Failed
Event* = object
## A timestamped event transition in a `Future` state.
Event* = object ## A timestamped event transition in a `Future` state.
future: FutureBase
newState*: ExtendedFutureState
timestamp*: Moment
EventCallback* = proc (e: Event) {.nimcall, gcsafe, raises: [].}
EventCallback* = proc(e: Event) {.nimcall, gcsafe, raises: [].}
var handleFutureEvent {.threadvar.}: EventCallback
proc `location`*(self: Event): SrcLoc =
@ -33,16 +32,12 @@ 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.} =
Event(future: future, newState: state, timestamp: Moment.now())
proc handleBaseFutureEvent*(future: FutureBase, state: FutureState): void {.nimcall.} =
{.cast(gcsafe).}:
let extendedState = case state:
let extendedState =
case state
of FutureState.Pending: ExtendedFutureState.Pending
of FutureState.Completed: ExtendedFutureState.Completed
of FutureState.Cancelled: ExtendedFutureState.Cancelled
@ -51,10 +46,12 @@ proc handleBaseFutureEvent*(future: FutureBase,
if not isNil(handleFutureEvent):
handleFutureEvent(mkEvent(future, extendedState))
proc handleAsyncFutureEvent*(future: FutureBase,
state: AsyncFutureState): void {.nimcall.} =
proc handleAsyncFutureEvent*(
future: FutureBase, state: AsyncFutureState
): void {.nimcall.} =
{.cast(gcsafe).}:
let extendedState = case state:
let extendedState =
case state
of AsyncFutureState.Running: ExtendedFutureState.Running
of AsyncFutureState.Paused: ExtendedFutureState.Paused
@ -73,4 +70,3 @@ proc stopMonitoring*() =
onBaseFutureEvent = nil
onAsyncFutureEvent = nil
handleFutureEvent = nil

105
chroprof/profiler.nim
View File

@ -10,37 +10,42 @@ import ./events
export timer, tables, sets, srcloc
type
FutureType* = SrcLoc
FutureType* = SrcLoc
## Within the scope of the profiler, a source location identifies
## a future type.
AggregateMetrics* = object
## Stores aggregate metrics for a given `FutureType`.
execTime*: Duration ## The total time that `Future`s of a given
## `FutureType` actually ran; i.e., actively
## occupied the event loop thread, summed
## accross all such `Futures`.
execTimeMax*: Duration ## The maximum time that a `Future` of a
## given `FutureType` actually ran; i.e.,
## actively occupied the event loop thread.
childrenExecTime*: Duration ## Total time that the children of `Future`s
## of this `FutureType` actually ran; i.e.,
## actively occupied the event loop thread,
## summed across all such children.
wallClockTime*: Duration ## Total time that the Future was alive;
## i.e., the time between the Future's
## creation and its completion, summed
## across all runs of this `FutureType`.
stillbornCount*: uint ## Number of futures of this `FutureType`
## that were born in a finished state;
## i.e., a `FutureState` that is not Pending.
callCount*: uint ## Total number of distinct `Future`s observed
## for this `FutureType`.
AggregateMetrics* = object ## Stores aggregate metrics for a given `FutureType`.
execTime*: Duration
## The total time that `Future`s of a given
## `FutureType` actually ran; i.e., actively
## occupied the event loop thread, summed
## accross all such `Futures`.
execTimeMax*: Duration
## The maximum time that a `Future` of a
## given `FutureType` actually ran; i.e.,
## actively occupied the event loop thread.
childrenExecTime*: Duration
## Total time that the children of `Future`s
## of this `FutureType` actually ran; i.e.,
## actively occupied the event loop thread,
## summed across all such children.
wallClockTime*: Duration
## Total time that the Future was alive;
## i.e., the time between the Future's
## creation and its completion, summed
## across all runs of this `FutureType`.
stillbornCount*: uint
## Number of futures of this `FutureType`
## that were born in a finished state;
## i.e., a `FutureState` that is not Pending.
callCount*: uint
## Total number of distinct `Future`s observed
## for this `FutureType`.
PartialMetrics = object
state*: ExtendedFutureState
@ -63,7 +68,8 @@ type
proc `execTimeWithChildren`*(self: AggregateMetrics): Duration =
self.execTime + self.childrenExecTime
proc push(self: var seq[uint], value: uint): void = self.add(value)
proc push(self: var seq[uint], value: uint): void =
self.add(value)
proc pop(self: var seq[uint]): uint =
let value = self[^1]
@ -71,7 +77,10 @@ proc pop(self: var seq[uint]): uint =
value
proc peek(self: var seq[uint]): Option[uint] =
if self.len == 0: none(uint) else: self[^1].some
if self.len == 0:
none(uint)
else:
self[^1].some
proc `$`(location: SrcLoc): string =
$location.procedure & "[" & $location.file & ":" & $location.line & "]"
@ -79,10 +88,8 @@ proc `$`(location: SrcLoc): string =
proc futureCreated(self: var ProfilerState, event: Event): void =
assert not self.partials.hasKey(event.futureId), $event.location
self.partials[event.futureId] = PartialMetrics(
created: event.timestamp,
state: Pending,
)
self.partials[event.futureId] =
PartialMetrics(created: event.timestamp, state: Pending)
proc bindParent(self: var ProfilerState, metrics: ptr PartialMetrics): void =
let current = self.callStack.peek()
@ -106,7 +113,7 @@ proc futureRunning(self: var ProfilerState, event: Event): void =
metrics.lastStarted = event.timestamp
metrics.state = Running
proc futurePaused(self: var ProfilerState, event: Event): void =
proc futurePaused(self: var ProfilerState, event: Event): void =
assert event.futureId == self.callStack.pop(), $event.location
assert self.partials.hasKey(event.futureId), $event.location
@ -136,7 +143,7 @@ proc futureCompleted(self: var ProfilerState, event: Event): void =
self.partials.withValue(event.futureId, metrics):
if metrics.state == Running:
self.futurePaused(event)
let execTime = metrics.partialExecTime - metrics.partialChildrenExecOverlap
aggMetrics.callCount.inc()
@ -152,16 +159,24 @@ proc futureCompleted(self: var ProfilerState, event: Event): void =
self.partials.del(event.futureId)
proc processEvent*(self: var ProfilerState, event: Event): void {.nimcall, gcsafe, raises: []} =
case event.newState:
of Pending: self.futureCreated(event)
of Running: self.futureRunning(event)
of Paused: self.futurePaused(event)
proc processEvent*(
self: var ProfilerState, event: Event
): void {.nimcall, gcsafe, raises: [].} =
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)
of Completed:
self.futureCompleted(event)
of Failed:
self.futureCompleted(event)
of Cancelled:
self.futureCompleted(event)
proc processAllEvents*(self: var ProfilerState, events: seq[Event]): void =
for event in events:
self.processEvent(event)
self.processEvent(event)

2
tests/testall.nim
View File

@ -3,4 +3,4 @@ import ./[testevents, testprofiler]
when defined(metrics):
import ./testmetricscollector
{.warning[UnusedImport]: off.}
{.warning[UnusedImport]: off.}

152
tests/testevents.nim
View File

@ -7,7 +7,6 @@ import ../chroprof/events
import ./utils
suite "event ordering expectations":
setup:
startRecording()
@ -15,38 +14,40 @@ suite "event ordering expectations":
stopRecording()
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"),
]
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"),
]
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.} =
@ -65,46 +66,57 @@ suite "event ordering expectations":
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"),
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 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 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"),
]
# 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.} =
@ -118,14 +130,20 @@ suite "event ordering expectations":
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"),
]
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"),
]

52
tests/testmetricscollector.nim
View File

@ -8,14 +8,14 @@ import chronos/[srcloc, timer]
import ../chroprof/[api, collector]
suite "metrics collector":
var locations = @[
SrcLoc(procedure: "start", file: "discovery.nim", line: 174),
SrcLoc(procedure: "start", file: "discovery.nim", line: 192),
SrcLoc(procedure: "query", file: "manager.nim", line: 323),
SrcLoc(procedure: "update", file: "sqliteds.nim", line: 107),
SrcLoc(procedure: "idle", file: "idle.nim", line: 100),
]
var locations =
@[
SrcLoc(procedure: "start", file: "discovery.nim", line: 174),
SrcLoc(procedure: "start", file: "discovery.nim", line: 192),
SrcLoc(procedure: "query", file: "manager.nim", line: 323),
SrcLoc(procedure: "update", file: "sqliteds.nim", line: 107),
SrcLoc(procedure: "idle", file: "idle.nim", line: 100),
]
let sample = {
locations[0]: AggregateMetrics(
@ -23,36 +23,36 @@ suite "metrics collector":
execTimeMax: timer.nanoseconds(80062),
childrenExecTime: timer.nanoseconds(52044),
wallClockTime: timer.nanoseconds(174567),
callCount: 1
callCount: 1,
),
locations[1]: AggregateMetrics(
execTime: timer.nanoseconds(91660),
execTimeMax: timer.nanoseconds(81660),
childrenExecTime: timer.nanoseconds(52495),
wallClockTime: timer.nanoseconds(72941),
callCount: 1
callCount: 1,
),
locations[2]: AggregateMetrics(
execTime: timer.nanoseconds(60529),
execTimeMax: timer.nanoseconds(60529),
childrenExecTime: timer.nanoseconds(9689),
wallClockTime: timer.nanoseconds(60784),
callCount: 1
callCount: 1,
),
locations[3]: AggregateMetrics(
execTime: timer.nanoseconds(60645),
execTimeMax: timer.nanoseconds(41257),
childrenExecTime: timer.nanoseconds(72934),
wallClockTime: timer.nanoseconds(60813),
callCount: 3
callCount: 3,
),
locations[4]: AggregateMetrics(
execTime: timer.nanoseconds(0),
execTimeMax: timer.nanoseconds(0),
childrenExecTime: timer.nanoseconds(0),
wallClockTime: timer.nanoseconds(60813),
callCount: 3
)
callCount: 3,
),
}.toTable
var wallTime = getTime()
@ -61,8 +61,12 @@ suite "metrics collector":
proc setupCollector(k: int = high(int)): void =
collector = ChronosProfilerInfo.newCollector(
sampler = proc (): MetricsTotals = sample,
clock = proc (): Time = wallTime,
sampler = proc(): MetricsTotals =
sample
,
clock = proc(): Time =
wallTime
,
sampleInterval = times.initDuration(minutes = 5),
k = k,
)
@ -74,16 +78,20 @@ suite "metrics collector":
setupCollector(k = 3)
check chronos_exec_time_with_children_total.value(
labelValuesParam = @["start", "discovery.nim", "192"]) == 144155
labelValuesParam = @["start", "discovery.nim", "192"]
) == 144155
check chronos_exec_time_with_children_total.value(
labelValuesParam = @["start", "discovery.nim", "174"]) == 142106
labelValuesParam = @["start", "discovery.nim", "174"]
) == 142106
check chronos_exec_time_with_children_total.value(
labelValuesParam = @["update", "sqliteds.nim", "107"]) == 133579
labelValuesParam = @["update", "sqliteds.nim", "107"]
) == 133579
# This is out of the top-k slowest, so should not have been recorded.
expect system.KeyError:
discard chronos_exec_time_with_children_total.value(
labelValuesParam = @["query", "manager.nim", "323"])
labelValuesParam = @["query", "manager.nim", "323"]
)
test "should not collect metrics again unless enough time has elapsed from last collection":
setupCollector()
@ -101,5 +109,5 @@ suite "metrics collector":
setupCollector()
expect system.KeyError:
discard chronos_exec_time_total.value(
labelValuesParam = @["idle", "idle.nim", "100"])
discard
chronos_exec_time_total.value(labelValuesParam = @["idle", "idle.nim", "100"])

473
tests/testprofiler.nim
View File

@ -9,267 +9,268 @@ import ../chroprof/profiler
import ./utils
suite "profiler metrics":
setup:
startRecording()
setup:
startRecording()
teardown:
stopRecording()
resetTime()
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()
proc recordedMetrics(): MetricsTotals =
var profiler: ProfilerState
profiler.processAllEvents(rawRecording)
profiler.metrics
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 blocking future":
proc simple() {.async.} =
advanceTime(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()
waitFor simple()
var metrics = recordedMetrics()
let simpleMetrics = metrics.forProc("simple")
var metrics = recordedMetrics()
let simpleMetrics = metrics.forProc("simple")
check simpleMetrics.execTime == 50.milliseconds
check simpleMetrics.wallClockTime == 50.milliseconds
check simpleMetrics.execTime == 20.milliseconds
check simpleMetrics.wallClockTime == 70.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)
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()
waitFor simple()
var metrics = recordedMetrics()
let simpleMetrics = metrics.forProc("simple")
var metrics = recordedMetrics()
let simpleMetrics = metrics.forProc("simple")
check simpleMetrics.execTime == 20.milliseconds
check simpleMetrics.wallClockTime == 70.milliseconds
check simpleMetrics.execTime == 30.milliseconds
check simpleMetrics.wallClockTime == 130.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)
test "should compute correct times when there is a single blocking child":
proc child() {.async.} =
advanceTime(10.milliseconds)
waitFor simple()
proc parent() {.async.} =
advanceTime(10.milliseconds)
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()
advanceTime(10.milliseconds)
waitFor parent()
except:
discard
advanceTime(10.milliseconds)
var metrics = recordedMetrics()
let parentMetrics = metrics.forProc("parent")
let childMetrics = metrics.forProc("child")
waitFor parent()
check parentMetrics.execTime == 20.milliseconds
check parentMetrics.childrenExecTime == 10.milliseconds
check parentMetrics.wallClockTime == 30.milliseconds
var metrics = recordedMetrics()
let parentMetrics = metrics.forProc("parent")
let childMetrics = metrics.forProc("child")
check childMetrics.execTime == 10.milliseconds
check childMetrics.wallClockTime == 10.milliseconds
check childMetrics.childrenExecTime == ZeroDuration
check parentMetrics.execTime == 20.milliseconds
check parentMetrics.childrenExecTime == 10.milliseconds
check parentMetrics.wallClockTime == 30.milliseconds
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)
check childMetrics.execTime == 10.milliseconds
check childMetrics.wallClockTime == 10.milliseconds
check childMetrics.childrenExecTime == ZeroDuration
proc parent() {.async.} =
advanceTime(10.milliseconds)
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 parent()
waitFor withFinally()
var metrics = recordedMetrics()
let parentMetrics = metrics.forProc("parent")
let childMetrics = metrics.forProc("child")
var metrics = recordedMetrics()
var withFinallyMetrics = metrics.forProc("withFinally")
check parentMetrics.execTime == 20.milliseconds
check parentMetrics.childrenExecTime == 20.milliseconds
check parentMetrics.wallClockTime == 90.milliseconds
check withFinallyMetrics.execTime == 30.milliseconds
check childMetrics.execTime == 20.milliseconds
check childMetrics.wallClockTime == 70.milliseconds
check childMetrics.childrenExecTime == ZeroDuration
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"))
test "should compute correct times when there are multiple blocking and non-blocking children":
proc blockingChild() {.async.} =
advanceTime(10.milliseconds)
var metrics = recordedMetrics()
proc nonblockingChild() {.async.} =
advanceTime(10.milliseconds)
await advanceTimeAsync(20.milliseconds)
advanceTime(10.milliseconds)
let stillborns = metrics.pairs.toSeq.map(
proc(item: (SrcLoc, AggregateMetrics)): uint =
item[1].stillbornCount
).sum
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
check stillborns == 2

23
tests/utils.nim
View File

@ -1,10 +1,9 @@
import chronos
import ../chroprof/[api, events, profiler]
type
SimpleEvent* = object
procedure*: string
state*: ExtendedFutureState
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
@ -16,7 +15,8 @@ var fakeTime*: Moment = Moment.now()
proc recordEvent(event: Event) {.nimcall, gcsafe, raises: [].} =
{.cast(gcsafe).}:
recording.add(
SimpleEvent(procedure: $event.location.procedure, state: event.newState))
SimpleEvent(procedure: $event.location.procedure, state: event.newState)
)
var timeShifted = event
timeShifted.timestamp = fakeTime
@ -25,10 +25,7 @@ proc recordEvent(event: Event) {.nimcall, gcsafe, raises: [].} =
proc recordSegment*(segment: string) =
{.cast(gcsafe).}:
recording.add(SimpleEvent(
procedure: segment,
state: ExtendedFutureState.Running
))
recording.add(SimpleEvent(procedure: segment, state: ExtendedFutureState.Running))
proc stopRecording*(): void =
recording = @[]
@ -50,20 +47,20 @@ proc resetTime*() =
proc advanceTime*(duration: Duration) =
fakeTime += duration
proc advanceTimeAsync*(duration: Duration): Future[void] =
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()):
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))
timer =
setTimer(Moment.fromNow(10.milliseconds), completion, cast[pointer](retFuture))
return retFuture