The primary goal of the profiler is to help identify performance issues in application code built on top of Chronos. In our context, "performance issues" boil down to one simple question:
What are, at a given time, the async procs that have occupied the event loop the most?
We will spend the rest of this document delving into how to answer this question. Section 2 constructs our understanding of what "occupying the event loop" means in terms of state tenancy on a simple, extended state machine for Futures which takes computation states into account. Section 3 then dives into the implementation hurdles and choices of actually tracking those extended states. Finally, Section 4 <<tbw>> presents extensions built for Codex and how they helped us identify bugs which would be otherwise very difficult to do.
\[ \newcommand{\pending}{\text{Pending}} \newcommand{\completed}{\text{Completed}} \newcommand{\failed}{\text{Failed}} \newcommand{\cancelled}{\text{Cancelled}} \newcommand{\running}{\text{Running}} \newcommand{\paused}{\text{Paused}} \]
Chronos can be thought of as a two-part system: a lower-level layer which undestands Futures and callbacks, and a higher-level layer which implements async/await primitives in terms of Futures and callbacks by means of macros and templates.
The lower-level futures, which we refer to as primitive futures, have four states (Fig. 1): an initial \(\pending\) state, and three finish states (\(\completed\), \(\failed\), and \(\cancelled\)). Note that this state machine does not have any intermediate states (e.g. a \(\running\) state): this is because what happens between \(\pending\) and any of the completion states; i.e., the actual computation, does not really concern Chronos at this level.
Indeed, such Futures could be doing anything: they could be waiting on a timer (e.g. as with asyncSleep), they could be waiting for data to be available on a socket (e.g. as with non-blocking network reads), or they could be waiting for a computation to finish on separate thread.
Figure 1. State machine for a primitive Future.
While primitive Futures offer a lot of flexibility, they are also of little interest to us - application code is typically not written with primitive Futures directly, as we will see in the next section. They also not have much structure for us to peek into and profile, and the best we can do is track the time elapsed from \(\pending\) to one of the completion states. Async Futures, which we will delve into next, are where the real opportunity for useful profiling lies.
Async Futures are Futures created from an async/await abstraction[1] using macros and templates. Consider the following simple example:
proc p() {.async.} =
echo "run segment 1"
await sleepAsync(1.seconds)
echo "run segment 2"
Listing 2. An async proc.
by expanding the async macro, we get:
proc p(): Future[void] {.stackTrace: false, gcsafe, raises: [].} =
iterator p_553648130(chronosInternalRetFuture: FutureBase): FutureBase {.
closure, gcsafe, raises: [Exception].} =
template result(): auto {.used.} =
{.fatal: "You should not reference the `result` variable inside" &
" a void async proc".}
block:
echo ["run segment 1"]
chronosInternalRetFuture.internalChild = sleepAsync(seconds(1))
yield chronosInternalRetFuture.internalChild
if chronosInternalRetFuture.internalMustCancel:
raise (ref CancelledError)(msg: "Future operation cancelled!")
internalCheckComplete(chronosInternalRetFuture.internalChild)
echo ["run segment 2"]
complete(cast[Future[void]](chronosInternalRetFuture), srcLocImpl("",
(filename: "weird.nim", line: 6, column: 2).filename,
(filename: "weird.nim", line: 6, column: 2).line))
let resultFuture =
newFutureImpl(srcLocImpl("p", (filename: "weird.nim", line: 5, column: 0).filename,
(filename: "weird.nim", line: 5, column: 0).line))
resultFuture.internalClosure = p_553648130
futureContinue(resultFuture)
return resultFuture
Listing 3. Macro expansion of an async proc.
What this does is that it transforms the body of our proc into a nim closure iterator (lines \(2\)–\(18\)), and then creates a Future object connected to that closure iterator (lines \(22\)–\(23\)). We cannot see this yet, but the completion of that resulting Future will be connected to the completion of the closure iterators by the Chronos runtime. The proc then returns that Future as its result (line \(25\)). From the perspective of the caller (and the lower-level layers of the Chronos runtime), this is just a Future like any other.
Now lets look at how the await primitive is implemented. The await primitive can be used inside of an async proc to interrupt its execution and resume it only after some specificed Future completes. Note that this can be any Future – primitive or async.
As we can see from Listing 3, a call to await gets expanded into:
chronosInternalRetFuture.internalChild = sleepAsync(seconds(1))
yield chronosInternalRetFuture.internalChild
if chronosInternalRetFuture.internalMustCancel:
raise (ref CancelledError)(msg: "Future operation cancelled!")
internalCheckComplete(chronosInternalRetFuture.internalChild)
what this does is:
sleepAsync(1.seconds) as specified in our proc's body. This returns a Future;yield, returning a reference to the child Future in its result.We are now ready to define what event loop occupancy means. We start by extending the state machine of a Future (Fig. 2) so that includes a \(\running\) and a \(\paused\) state. We then define these states as follows:
iterator.finished() will return false.Figure 2. Extended state machine for async Futures.
Event Loop Occupancy Time. We define the time that an async proc has occupied the event loop as the total time its async Future spent in \(\running\) state.
This section delves into more details as to how the implementation works, as well as its current shortcomings.
Throughout this section, we should keep the following implementation desiderata in mind. We strive for:
Note that (1) trumps (2), so we will happily tradeoff making a simpler and shorter change on the core for a slightly less efficient or more complicated profiler. This leads to the third item in the desiderata:
The intent is to keep the profiler as unintrusive as possible, while at the same time making it easier to maintain. The more we touch the complicated parts of Chronos, the more likely it is that the profiler may introduce issues, and the more likely it is that it gets dropped as being too complex or burdensome to maintain.
The first idea that comes to mind as we try to track the moments at which an async Future transitions from and to \(\running\) and \(\paused\) states is finding where the code that actually calls the iterator resides and putting instrumentation points around it.
If we look into the expanded async proc of Listing 3, we see that before the proc actually returns the Future, it performs a call to futureContinue in line \(24\). The key points of futureContinue are shown in Listing 4.
proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} =
# This function is responsible for calling the closure iterator generated by
# the `{.async.}` transformation either until it has completed its iteration
# or raised and error / been cancelled.
#
# Every call to an `{.async.}` proc is redirected to call this function
# instead with its original body captured in `fut.closure`.
var next: FutureBase
template iterate =
while true:
# Call closure to make progress on `fut` until it reaches `yield` (inside
# `await` typically) or completes / fails / is cancelled
next = fut.internalClosure(fut)
if fut.internalClosure.finished(): # Reached the end of the transformed proc
break
if next == nil:
raiseAssert "Async procedure (" & ($fut.location[LocationKind.Create]) &
") yielded `nil`, are you await'ing a `nil` Future?"
if not next.finished():
# We cannot make progress on `fut` until `next` has finished - schedule
# `fut` to continue running when that happens
GC_ref(fut)
next.addCallback(CallbackFunc(internalContinue), cast[pointer](fut))
# return here so that we don't remove the closure below
return
# Continue while the yielded future is already finished.
# ...
try:
iterate
except CancelledError:
fut.cancelAndSchedule()
except CatchableError as exc:
fut.fail(exc)
except Exception as exc:
if exc of Defect:
raise (ref Defect)(exc)
Listing 4. futureContinue
We see here that futureContinue will immediately enter a loop (line \(10\)) which will repeatedly invoke the closure iterator (line \(13\)) until either:
Case (1) means the async Future has reached a finish state, whereas case (2) means it is \(\paused\). We will not deal with finish states here as those also concern primitive Futures and are dealt with elsewhere (Sec. 3.2).
To track \(\running\)/\(\paused\), we add two instrumentation points around the call to the closure iterator, which emit events as the iterator is called/yields:
when chronosProfiling:
if not isNil(onFutureExecEvent):
onFutureExecEvent(fut, Running)
while true:
# Call closure to make progress on `fut` until it reaches `yield` (inside
# `await` typically) or completes / fails / is cancelled
next = fut.internalClosure(fut)
if fut.internalClosure.finished(): # Reached the end of the transformed proc
break
if next == nil:
raiseAssert "Async procedure (" & ($fut.location[LocationKind.Create]) &
") yielded `nil`, are you await'ing a `nil` Future?"
if not next.finished():
when chronosProfiling:
if not isNil(onFutureExecEvent):
onFutureExecEvent(fut, Paused)
# ...
Listing 6. Instrumentation points which track Run/Pause states.
These are largely enough for us to know when an async Future is \(\running\) and when it is \(\paused\) though, as we will see, we need to do some tricks to cover some edge cases like fully-blocking children (Sec. 3.3).
We need two more instrumentation points to track state transitions into \(\pending\) and the finish states. Somewhat predictably, \(\pending\) gets tracked as the future is created, in internalInitFutureBase:
proc internalInitFutureBase*(
fut: FutureBase,
loc: ptr SrcLoc,
state: FutureState) =
# ...
when chronosProfiling:
if not isNil(onFutureEvent):
onFutureEvent(fut, state)
this also covers some edge cases in which Futures are created already in a finish state. Such cases are currently largely ignored by the profiler as there is nothing to measure.
Finally, every Future in Chronos will call the finish proc once it reaches a finish state, and that is where our final instrumentation point is:
proc finish(fut: FutureBase, state: FutureState) =
# We do not perform any checks here, because:
# 1. `finish()` is a private procedure and `state` is under our control.
# 2. `fut.state` is checked by `checkFinished()`.
fut.internalState = state
when chronosProfiling:
if not isNil(onFutureEvent):
onFutureEvent(fut, state)
when chronosStrictFutureAccess:
doAssert fut.internalCancelcb == nil or state != FutureState.Cancelled
fut.internalCancelcb = nil # release cancellation callback memory
for item in fut.internalCallbacks.mitems():
if not(isNil(item.function)):
callSoon(item)
item = default(AsyncCallback) # release memory as early as possible
Our definition of event loop occupancy, while simple, has issues with the way Chronos works as Chronos always executes the first iteration of a child's closure iterator as part of the parent (i.e., before yielding back to the event loop). This means that there is an overlap in run states, and that we end up - as things are - billing occupancy both to the parent and to the child.
To understand how this happens, note that any (macro expanded) async proc will end with the following snippet:
let resultFuture =
newFutureImpl(srcLocImpl("p", (filename: "weird.nim", line: 5, column: 0).filename,
(filename: "weird.nim", line: 5, column: 0).line))
resultFuture.internalClosure = p_553648130
futureContinue(resultFuture)
return resultFuture
Let us call this the return snippet. Remember, every async proc has one. So, if we have a parent doing:
proc child() {.async.} =
expensiveSlowComputation()
await asyncSleep(1.seconds)
proc parent() {.async.} =
await child()
then the return snippet on the child will run in the child before it returns to the to the parent. Since the parent will only yield a Future after it is returned to it, this means that the first part of the child will run before the yield. This means we will not trigger the \(\paused\) instrumentation point before then.
But at that point expensiveSlowComputation() already ran. If we do not do anything, we will end up billing this on the parent. Indeed, the event order we get is the following:
parent: Pending
parent: Running --------------------------------------------|
parent: echo "segment 1" |
child: Pending |
child: Running ----------------------| | Parent is Running
child: expensiveSlowComputation() | Child Overlap |
child: Paused -----------------------| |
parent: Paused ---------------------------------------------|
The way we account for this overlap is by adding another condition to the definition of \(\paused\), namely:
iterator.finished() will return false; or;We do not add any more explicit instrumentation points to make this work. Instead, we account for this by tracking the time elapsed for the first transition from \(\running\) to \(\paused\) on every child on the profiler side, and deducting that from the parent once the child completes.
The profiler keeps an internal table with information on running Futures which accrues execution time for every Future. The reason we do this is so we can have per-call statistics on async procs (e.g. which call took the longest, what was the average call duration, percentiles, etc).
Because there might be many calls during the lifetime of a program, this table needs to be garbage collected. The natural moment to do this garbage collection is when a Future completes: we get our data, accrue them into stats, then delete the entry for that Future.
The problem is that because of the issue discussed in Sec. 3.3 we have that non-blocking children, i.e., children that never yield, will run to completion before their parent has a chance to even know it had a child. By then, it is too late to accrue children metrics on the parent and correct the run state overlaps, as those will be gone from the table.
Since Chronos is single-threaded, the way we deal with this is by implicitly assuming that any async Future that enters a \(\running\) state while there is another async Future already in that state must be a child. Because we will not get any extra events from the instrumentation to keep track of this, we need to keep a stack on the profiler side which pushes a Future id on \(\running\), and pops it on \(\paused\). Note that by looking exclusively at \(\running\) and \(\paused\) we are guaranteed not to inadvertently track primitive Futures.
We do not like this solution much. Corner cases may still exist which break the stack invariants (e.g. an async Future which calls a primitive Future which calls an async Future somehow) but for now this works.
The other option would be changing the async macros so that children know they have a parent and can then tell the profiler about it before they start running, but that will require fiddling with macros and figuring out a way to pass that information without changing the child's signature, e.g. as parameter with a mangled name and nil default. If the profiler ever goes "mainstream", that would probably be a better way to go.
waitFor and Nested Calls to Poll<<TBW>>
We assume the reader to be familiar with async/await and why it is useful. ↩︎
-
Any changes
Be notified of any changes
-
Mention me
Be notified of mention me
-
Unsubscribe
Subscribe