\[ \newcommand{\pending}{\text{Pending}} \newcommand{\completed}{\text{Completed}} \newcommand{\failed}{\text{Failed}} \newcommand{\cancelled}{\text{Cancelled}} \newcommand{\running}{\text{Running}} \newcommand{\paused}{\text{Paused}} \]

1. Introduction

One standard feature of profilers is allowing a tree view where the execution time of a proc can be broken down into its own execution time plus the execution times of the procs it calls (its children in the tree). Fig. 1 shows an example of such a performance tree taken from the RStudio profiler as it runs the program in Listing 1.

Figure 1. Tree view in the RStudio profiler.

parent <- function() {
  lapply(1:1000000, function(x) x + 1)
  child1()
  child2()
}

child2 <- function() {
  lapply(1:1000000, function(x) x + 1)
  NULL
}

child1 <- function() {
  child2()
}
         
parent()

Listing 1. R program giving raise to the performance tree in Fig. 1.

The main reason the tree view is useful is that it provides a snapshot of causality: each path running root-to-leaf represents a call chain that actually happened, with the contributions of each individual call as well as the cause for those calls happening (i.e., who was the caller) clearly mapped out. While this makes them very handy for tracking down issues, the downside is that performance trees can be expensive to build and maintain.

Flattened performance ranks. To make our lives easier at first, we would be happy with a proxy for a performance tree that is much simpler and cheaper to build: we call those flattened performance ranks, or just performance ranks for short (Figure 2). A performance rank is a simple one-dimensional flattening of the tree so that performance numbers are aggregated across paths and nodes: "exec time w/ children" represents a path aggregation in Figure 2, and those get further aggregated by nodes referring to the same proc. As we place those in the real line, we can rank the procs and see their overall time expenditure, as well as the time expenditure spanning from their actions (i.e. children that they started).

This is of course not nearly as informative as a performance tree, but it is more than enough for us to identify that the proc that is issuing slow calls is parent, and that the slow computation that may warrant optimization is in child2.

Figure 2. Performance tree and equivalent flattened rank.

Regardless of whether we build a full-fledged performance tree, a flattened performance rank, or a call graph, the key point is that those all depend on how parent/child relationships are defined, and that is where it starts to get murky with Chronos. We discuss some of the issues involved in Section 2, and explain how we have so far addressed them in Section 3. Finally, in Section 4 we provide a real-world example of how performance ranks can be sampled and transformed into time series to follow the execution and debug a real issue.

2. Challenges in Building a Performance Tree in Chronos

Differing semantics. The meaning for "child" and "parent" in Chronos is different from what you typically expect. Indeed, in Chronos, a Future \(f_c\) becomes a child of another Future \(f_p\) if and only if:

• \(f_p\) is an async Future;
• \(f_p\) awaits for \(f_c\).

In Chronos, therefore, we can say that the child of relationship is just the inverse of the awaits for relationship; i.e., if \(f_p\) awaits for \(f_c\) then \(f_c\) is a child of \(f_p\). This is rather different from the caller/callee relationship you get in a regular program, and can result in surprising results if we adopt it as is.

To see why, consider what would happen if we were to accrue execution times from children into parents as we typically do when building a performance tree for the following program:

proc child(): Future[Something] {.async.} = 
  result = # perform some very expensive computation
           # and block the event loop for 1h
          
proc parent1(): Future[Future[Something]] {.async.} = 
  result = child()
  discard await result

proc parent2(fosterChild: Future[Something]) {.async.} = 
  discard await fosterChild
  
let fut = waitFor parent1()
waitFor parent2(fut)

Since the Future generated by the call to child is awaited by both parent1 (line \(7\)) and parent2 (line \(10\)), this would mean we would count the execution time of both as having taken \(1\text{h}\) when factoring in their children (Fig. 2), which does not make a lot of sense. Indeed, it may actually throw off the user trying to find the cause of the issue as they inspect parent2 only to find it is not to blame for the performance issue; i.e., it did not cause it. If we aggregate those over longer paths, things can get even more confusing, particularly as those form DAGs and not trees.

Figure 2. Performance metrics on parent and children.

Garbage collection. Suppose we still wanted to aggregate metrics from children into parents using the awaits for relationship above. Execution metrics are tracked per-Future, which means that if we want to accrue child execution time at the parent, then we must keep the child metrics around until no other parents can show up. Because Chronos allows awaiting on Futures even after they are finished, however, this means new parents can be added arbitrarily far into the future.

Indeed, as long as a reference to \(f_c\) exists, there may still be other async procs that can await on \(f_c\) and become their parent, even far after the \(f_c\) has reached a finish state. This leaves us with an uncomfortable problem: either we keep metrics for finished Futures forever, and leak memory, or we rely on broken finalizers to get rid of them, neither of which is a compelling solution.

3. Parent/Child Relationships in Chroprof

Chroprof tackles the above issues by defining parent/children relationships that are more similar to how they are defined in a regular program. For given futures \(f_p\) and \(f_c\), we say that \(f_c\) is a child of \(f_p\) if an only if:

1. \(f_p\) is a Future;
2. \(f_c\) has been created by \(f_p\) or, equivalently^[1], \(f_c\) was created while \(f_p\) was in \(\running\) state.

What defines parent-child relationships then, in this case, is creation, not whether or not some Future awaited on another.

This corrects the anomaly we had seen in Figure 2. Indeed, under this new definition parent2 is no longer a parent of child since it did not create it, and therefore does not getchild's metrics accounted into its "exec time with children".

Figure 3. Performance metrics of parent and children in Chroprof.

Garbage collection. Our new definition for parent/child means that the parent for a Future is defined at the moment it is created and never changes. This means we can easily track the lifetime of parent and child Futures on the profiler side and garbage collect partial metrics once both are completed, no finalizers needed.

Execution overlap. Finally, this definition also helps with correcting metrics in execution overlap: since we are tracking that \(f_p\) created \(f_c\), we know that the first iteration of the \(f_c\) happened as part of \(f_c\)'s execution, and can deduct the correct value once \(f_c\) completes.

4. Performance Ranks in Practice

Performance ranks built on top of the Chroprof parent/child relationship have proven to be of valuable help. Figure 4 (click here if the plot does not load) shows one such occasion, where Codex was slowing during an upload/download experiment. The chart is constructed by looking at metrics aggregated in performance ranks and de-accumulating them to provide a sort of "CPU usage" view for the Chronos event loop over 60s time intervals.

It's easy to spot that taskHandler is doing something strange, and that it progressively occupies the event loop more and more until collapse. By spotting the proc immediately below it, one can also infer that taskHandler is doing too many localLookups, which turns out to be the case as one inspects the code for taskHandler. By crossreferencing this with logs, I was able to determine that cancellations were not working.

Figure 4. Profiler metrics from a Codex run with a performance bug in taskHandler. Click here if the plot does not load.