Writing a Tracing Framework, Part 3: Concurrency

The end of part 2 alluded to a problem with the API handling multiple events. By design, Minitrace.add_field and Minitrace.add_fields make it so we don’t have to pass a Minitrace::Event object around all over the code, but that bakes in the assumption that we only work on one event at a time (from the nearest enclosing Minitrace.with_event).

And this is largely true! We typically expect control flow to move in a predictable fashion, only exiting the .with_event block when all the work is done, so the event can/should be fired at the end of the block as well. But that picture changes when we add concurrency to the mix. Now instead of the block having to finish first, it could actually be performing its work at some arbitrary other time. What would need to change about how we handle the corresponding event?

Synchrony

At a high level, we like to assume our code executes roughly the same way that it reads: sequentially, one line at a time. Constructs like if statements or while loops might jump us to some different line of code, but at least they’re explicit, predictable, and limited to some specific syntax. A function call will also transfer control to some other line of code, changing some local variable bindings and such (hence the need to push frames onto the call stack), but execution continues linearly in that function’s definition thereafter. Once we finish in the function, we return back to the original call site (popping the stack frame).

We’ve mirrored the call stack structure in the minitrace API. Instead of function calls, we have Minitrace.with_event blocks. Rather than stack frames, we push Minitrace::Event instances. Like the local variable bindings in each frame, we have key/value pairs in each event via Minitrace::Event#fields. As with function returns, the top of the stack is popped when the block ends.

By replicating this, though, we’ve tacitly made the assumption that these blocks are synchronous. That is, each block executes at the same time as when we invoke .with_event, just as a function’s body is evaluated as soon as we call it. This is a sensible default; most programming languages work this way (excusing, for example, lazily-evaluated ones like Haskell). It makes reasoning about the code easier as a reader, but it can also lead to inefficiencies in practice.

A common illustration here might be something like fetching a list of URLs, but that’s boring and overdone. Instead, as a sillier running example, imagine Goldilocks and the titular three bears are all sitting down at a restaurant and ordering their respective porridges. The synchronous way for the waiter to take their orders is to go around the table one person/bear at a time. This is no problem for our current minitrace API, so we can instrument the code successfully:

# Synchronous
[goldilocks, papa, mama, baby].each do |diner|
  Minitrace.with_event do
    Minitrace.add_field("diner", diner.name)
    porridge = diner.choose_porridge
    Minitrace.add_field("porridge_temp", porridge.temp)
    waiter.write_down(porridge)
  end
end

The waiter’s loop goes to each diner in turn and calls their #choose_porridge method. This vaguely “looks” synchronous, since we assign that return value to the porridge variable and continue to call the waiter’s #write_down method as if we have the concrete porridge choice in hand. (This might seem weird to point out now, but it’ll make more sense when contrasted with asynchronous code later.)

We generate one event for each of the diners. Within each event, we can reason that the block body executes each line sequentially, thus going in the order:

1. add the "diner" field to the current event
2. choose the porridge
3. add the "porridge_temp" field to the current event
4. write down the porridge choice
5. fire the current event, popping it from the stack

Because we fire one event before moving onto the next, we know that they should come in like this:

[
  { "diner" => "Goldilocks", "porridge_temp" => "just right" },
  { "diner" => "Papa Bear", "porridge_temp" => "too hot" },
  { "diner" => "Mama Bear", "porridge_temp" => "too cold" },
  { "diner" => "Baby Bear", "porridge_temp" => "just right" },
]

There’s a clear benefit to this predictable behavior, but the drawback of #choose_porridge being synchronous is that we have to wait for it to finish executing each time it’s called. The three bears all have their go-to orders, so they will respond very quickly. But as we start going around the table, Goldilocks sits there being indecisive! The whole loop is said to be blocked on goldilocks.choose_porridge. As we wait for her to finally make her order, the bears are idly waiting. They could have all ordered in the time it took Goldilocks to argue with herself about the ideal porridge temperature.

We want a smarter way to interleave the diners’ decisions so we serve them as fast as possible. Broadly speaking, there are two strategies to accomplish this: cooperative multitasking and pre-emptive multitasking.

Asynchrony

In common usage, asynchronous programming tends to be synonymous with cooperative multitasking. Strictly it just means not-synchronous, which invites some confusion and opens up Pandora’s box on a whole host of interrelated topics: multi-core processors, OS processes, kernel threads, green threads, fibers, event loops, continuations, coroutines, async/await, futures and promises, the actor model, etc.

Lest the bears wait so long that they get hungry and eat Goldilocks (causing a whole scene), we’ll limit the conversation a bit. Fortunately for Ruby, all of its asynchronous abstractions build on top of the humble block, which is effectively Ruby’s equivalent of an anonymous function. Higher-level constructs like Fiber will require passing around blocks at some point, so the surface area for our API changes should be low.

First, let’s understand what cooperative multitasking means in our Goldilocks example. As the name implies, this style of multitasking is when the task-doers play nicely together. Instead of blocking, they defer to some form of external scheduler (e.g., Ruby’s fiber scheduler). At our dining table, that means the waiter turns to Goldilocks who, knowing she’s going to be slow, waves them on: “come back to me later, I’m still deciding”. The waiter can then turn to the next diner (Papa Bear), giving Goldilocks time to do her thinking.

Supposing that everyone is cooperating, the waiter won’t get anybody’s order on the first pass through the table. They get polite deferrals from Papa, then Mama, then Baby, and finally there’s nothing else to do. Only then can the waiter decide to check back in on any undecided patrons, turning to Goldilocks once again. If she’s finished deciding, her order can be written down; if not, the waiter moves on to the next pending diner. Notice how this means that the porridge choices might be received in an unpredictable order, depending on when the waiter loops back around to an undecided diner and whether that diner finally responds on this go-around. For instance, maybe Goldilocks yields again, but all the bears reply on the second round, finishing ahead of her.

Putting this to Ruby code, instead of a function call evaluating immediately, it returns immediately, but must take an extra block argument referred to as a callback (because we’re going to “call it back” later). The idea is that the function’s body is evaluated by the async runtime (e.g., the Async gem). Since we’re being cooperative, the function’s pending work is only executed if there’s no other synchronous work currently in progress, which keeps at least some of the predictable control flow we enjoyed before. Once the function actually finishes, instead of returning a value, the runtime invokes the callback with that value for any subsequent processing. Passing these extra callback blocks is thus effectively mimicking continuation-passing style.

Instead of our synchronous #choose_porridge method, let’s imagine an asynchronous version called #async_choose_porridge:

# Mixed sync/async (buggy)
[goldilocks, papa, mama, baby].each do |diner|
  Minitrace.with_event do
    Minitrace.add_field("diner", diner.name)
    diner.async_choose_porridge do |porridge|
      # BUG: what's at the top of the event stack here?
      Minitrace.add_field("porridge_temp", porridge.temp)
      waiter.write_down(porridge)
    end
  end
end

Rather than return a value we can assign to the porridge variable, the diner.async_choose_porridge call now takes in a callback that gets stashed for later, and the loop continues on. The callback takes in porridge as a parameter, so once it’s invoked, we can continue on to the associated waiter.write_down(porridge) logic.

We like the way Minitrace.with_event works synchronously, but if we mix it with this asynchronous method, we run into problems. Now the Minitrace.add_field inside the callback might be invoked at some undetermined future time. In this simplistic example where we only have the one loop, we bulldoze through all four diners on the first pass, synchronously firing all the events we started in the loop body:

[
  { "diner" => "Goldilocks" },
  { "diner" => "Papa Bear" },
  { "diner" => "Mama Bear" },
  { "diner" => "Baby Bear" },
]

Then, since there’s now no more synchronous work to do, we start processing the pending async logic. We’ll eventually invoke all the callbacks, but by that point the Minitrace.events stack is empty and the "porridge_temp" fields have nowhere to go!

Because we don’t know order in which the callbacks might ultimately fire, there’s no real way to look at just one “spot” like the top of a stack. We still start the event outside of the callback just fine, but then we need some way of referring to that specific event inside the callback so we can call Minitrace::Event#fire at the actual end of the computation. Normally this is done through closures, where the callback can capture some variable from the outer lexical scope. So instead of using Minitrace.with_event, the most straightforward thing we could do is handle a raw Minitrace::Event instance:

# Async
[goldilocks, papa, mama, baby].each do |diner|
  event = Minitrace::Event.new
  event.add_field("diner", diner.name)
  diner.async_choose_porridge do |porridge|
    event.add_field("porridge_temp", porridge.temp)
    waiter.write_down(porridge)
    event.fire
  end
end

This version now works. The events are still created as we pass through the loop, so we can add the "diner" field at the start. We then refer the outer scope’s event variable from within the callback, thus being able to add the "porridge_temp" field and ultimately fire the event.

Admittedly, we’re not leveraging any of the API we created before. However, this is a cost we generally have to pay for the shape of async code, especially when dealing directly with callbacks (they call it callback hell for a reason). Given that any higher-level async abstractions are likely too specific for us to develop any more sophisticated minitrace API, basically it just has to be the contract that, for async events, it’s the user’s responsibility to create them, pass them around, and fire them. Fields are also added directly rather than through through module-level methods.

We don’t strictly need anything more than Minitrace::Event.new, but it makes me feel better to at least acknowledge the distinction with a top-level method:

module Minitrace
  class << self
    def event
      Minitrace::Event.new
    end
  end
end

Notice we do nothing with the event itself, like pushing it to the stack. The understanding is that Minitrace.event is for async code, which should be handled separately from the synchronous Minitrace.with_event + Minitrace.add_field + Minitrace.add_fields API.

Safety

Having decided to separate our asynchronous (lack of) API from the synchronous API, we currently have little more than convention preventing misuse. For example, right now we allow code like this:

Minitrace.with_event do
  Minitrace.add_field("event", "A")

  # Let's say that somehow this happens
  event = Minitrace.event
  event.add_field("event", "B")
  Minitrace.events << event
end

First, Minitrace.with_event pushes a new (synchronously managed) event A onto the stack. Then, inside the block, we manually push a second (asynchronously managed) event B onto the stack. At the end of the block, .with_event pops the top and fires. But the event it gets back is B instead of A. So now A is still left hanging out on the stack!

While Ruby is perhaps too dynamic to “properly” prevent us from mutating the Minitrace.events stack in such ways (as long as the method is public), we can still code defensively in the .with_event method to guard against such bugs. Thus, we define a Minitrace::SyncError exception class and use it enforce our expected invariant:

     def with_event
-      events << Minitrace::Event.new
+      event = Minitrace::Event.new
+      events << event
       yield
     ensure
-      events.pop.fire
+      pending = events.pop
+      raise Minitrace::SyncError.new(event, pending) unless event == pending
+      pending.fire
     end

Since we have the local variable event within the .with_event definition, we can check it against the top of the stack we get in the ensure block. If the objects aren’t equal, then something has gone wrong and we raise a fuss.

Threading

That wraps up cooperative multitasking, leaving us with its counterpart, pre-emptive multitasking. In this paradigm, task-doers get no say in whether they yield control to each other. Instead, some external scheduler (like the operating system) interrupts workers in the middle of their tasks to switch to some other worker. This is mainly implemented via multithreading, whether using lower-level operating system kernel threads or higher-level language runtime threads.

Applying this to our fantasy restaurant, none of the diners are polite anymore. Instead, the waiter is rude. Goldilocks is slow to respond, but rather than hold out for her, the waiter throws up their hands: “JEEZ LADY, I ain’t got all day! Papa Bear, are you ready?” The waiter will bounce around the table according to their own whims until everyone’s orders are in. Simple, but effective!

In Ruby, each diner would be put on a separate Thread:

# Threaded
[goldilocks, papa, mama, baby].each do |diner|
  Thread.new do
    Minitrace.with_event do
      Minitrace.add_field("diner", diner.name)
      porridge = diner.choose_porridge
      Minitrace.add_field("porridge_temp", porridge.temp)
      waiter.write_down(porridge)
    end
  end
end

This code looks virtually identical to our synchronous loop, just with the addition of the Thread.new wrapping the loop body, thereby creating a new background thread for each diner. (In a real program, we’d also need some plumbing to make sure the main thread stays alive until all the background threads finish, but that’s not really important for the example. Just imagine all the threads finish eventually.)

However, unlike the linear control flow of our synchronous code or the callback-based control flow of cooperative multitasking, the control flow here is deceptive. Because the Ruby thread scheduler can just decide to pre-emptively interrupt any thread, we might be in the middle of a block before suddenly switching contexts. This wouldn’t be too much of a problem except that one of the key features of threads is they still share memory. In our case, the dangerous part is our Minitrace.events stack, which we defined previously as

module Minitrace
  class << self
    def events
      @events ||= []
    end
  end
end

It hardly seems like anything could be wrong with it: it’s just using a variable to hold onto an array. We decided this didn’t make sense for our asynchronous API, but it should be fine for our synchronous API, right?

Yet a .with_event block that by all appearances looks synchronous may in fact be interrupted by a thread, and that thread will still be referencing the same underlying @events class-level instance variable in the Minitrace module. As threads swap in & out, we can’t be sure the order in which any of their individual operations run in relation to each other. This opens us up to race conditions where we have two threads competing to pull ahead of each other.

For illustration, consider two of our threads from above: one for goldilocks, one for papa. Let’s call them goldilocks_thread and papa_thread, respectively. As we enter the Minitrace.with_event block on either thread, they’ll push their corresponding events (creatively dubbed goldilocks_event and papa_event) to the Minitrace.events array. Suppose the threads interrupt each other back & forth such that this is the order of operations:

1. switch to goldilocks_thread
2. Minitrace.events << goldilocks_event
3. 🟢 add "diner" field to top event, so goldilocks_event.add_field("diner", "goldilocks")
4. switch to papa_thread
5. Minitrace.events << papa_event
6. 🟢 add "diner" field to top event, so papa_event.add_field("diner", "papa")
7. switch to goldilocks_thread, calling goldilocks.choose_porridge
8. 🔴 add "porridge_temp" field to top event, so papa_event.add_field("porridge_temp", "just right")
9. finish block and fire top event, so papa_event.fire
10. switch to papa_thread, calling papa.choose_porridge
11. 🔴 add "porridge_temp" field to top event, so goldilocks_event.add_field("porridge_temp", "too hot")
12. finish block and fire top event, so goldilocks_event.fire

Because the threads pre-empted each other but share the same stack, they wind up clobbering the wrong "porridge_temp" fields on both events (steps 8 & 11)! Of course, this is just one possible scenario. There are other insidious bugs that could come up from different unfortunate orderings.

This behavior is unpredictable enough that it’s simplest to instead maintain a separate stack for each thread. If threads really want to share an event (which seems unlikely), they can use the async API and figure out a safe way to pass the Minitrace::Event between themselves. We can limit the scope in Ruby using a thread-local variable (technically fiber-local, but the distinction isn’t worth belaboring):

module Minitrace
  class << self
    def events
      Thread.current["Minitrace.events"] ||= []
    end
  end
end

Now instead of the @events variable that’s shared between all threads, we look up Thread.current["Minitrace.events"] as an array kept scoped only to the current thread. This neatly solves our state problems without the need for any fancier thread synchronization mechanisms, and otherwise our example code can generally just use the synchronous API. In fact, this makes the comparison to the call stack even stronger: when threads context switch, they also have to save the current call stack and it keep it separate from the other threads, just as we’re doing with the event stack. Also note that the synchronous API still works even if we never call Thread.new, since there is tacitly at least one thread in any running Ruby program, so Thread.current always has a valid value.

Up Next

Whew! That was a lot to say about what amounted to very few actual code changes. I’d originally tried to cram this material into the end of part 2, but found it too difficult trying to explain the subtleties of concurrent code. It’s a good thing we gave this topic its due, though, because said subtlety is notorious for causing a lot of tricky bugs.

With that hard thinking out of the way, we can start paying attention to actually tracing stuff. In particular, I think we’ll be pleasantly surprised at how quickly we can go from these humble structured events to full-fledged traces just by adding the right fields & values, leveraging our API so it all comes together quite naturally.

The full code changes made for this post can be found on GitHub:

• a79756a Define module-level API for asynchronous events
• e72dfcd Ensure synchronous operations are thread-safe
• 8cf4ca9 Code defensively around synchronization errors