diff --git a/chroprof.nim b/chroprof.nim index 22a446e..1e477cb 100644 --- a/chroprof.nim +++ b/chroprof.nim @@ -3,4 +3,4 @@ when not defined(chronosProfiling): import ./chroprof/api -export api \ No newline at end of file +export api diff --git a/chroprof.nimble b/chroprof.nimble index a640595..7ab8af3 100644 --- a/chroprof.nimble +++ b/chroprof.nimble @@ -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" \ No newline at end of file + exec "nim c --out:./build/testall --mm:refc -d:metrics -r tests/testall.nim" diff --git a/chroprof/api.nim b/chroprof/api.nim index d7257cf..8c29c30 100644 --- a/chroprof/api.nim +++ b/chroprof/api.nim @@ -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) ) diff --git a/chroprof/collector.nim b/chroprof/collector.nim index 714f7ed..e7426d6 100644 --- a/chroprof/collector.nim +++ b/chroprof/collector.nim @@ -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() ) - diff --git a/chroprof/events.nim b/chroprof/events.nim index 5ac23f2..5f6484d 100644 --- a/chroprof/events.nim +++ b/chroprof/events.nim @@ -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 - diff --git a/chroprof/profiler.nim b/chroprof/profiler.nim index f1c55a1..c04f3fa 100644 --- a/chroprof/profiler.nim +++ b/chroprof/profiler.nim @@ -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) \ No newline at end of file + self.processEvent(event) diff --git a/tests/testall.nim b/tests/testall.nim index b42eef7..a630f93 100644 --- a/tests/testall.nim +++ b/tests/testall.nim @@ -3,4 +3,4 @@ import ./[testevents, testprofiler] when defined(metrics): import ./testmetricscollector -{.warning[UnusedImport]: off.} \ No newline at end of file +{.warning[UnusedImport]: off.} diff --git a/tests/testevents.nim b/tests/testevents.nim index ed23e0c..e5b4617 100644 --- a/tests/testevents.nim +++ b/tests/testevents.nim @@ -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"), - ] \ No newline at end of file + 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"), + ] diff --git a/tests/testmetricscollector.nim b/tests/testmetricscollector.nim index 99a7199..b594ef8 100644 --- a/tests/testmetricscollector.nim +++ b/tests/testmetricscollector.nim @@ -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"]) diff --git a/tests/testprofiler.nim b/tests/testprofiler.nim index 0d9dcc3..f88fb1f 100644 --- a/tests/testprofiler.nim +++ b/tests/testprofiler.nim @@ -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 \ No newline at end of file + check stillborns == 2 diff --git a/tests/utils.nim b/tests/utils.nim index 8bbd124..bf11c9d 100644 --- a/tests/utils.nim +++ b/tests/utils.nim @@ -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