Execution tracer overhaul

Authored by [email protected] with a mountain of input from others.

In no particular order, thank you to Felix Geisendorfer, Nick Ripley, Michael Pratt, Austin Clements, Rhys Hiltner, thepudds, Dominik Honnef, and Bryan Boreham for your invaluable feedback.

§ Background

Original design document from 2014.

Go execution traces provide a moment-to-moment view of what happens in a Go program over some duration. This information is invaluable in understanding program behavior over time and can be leveraged to achieve significant performance improvements. Because Go has a runtime, it can provide deep information about program execution without any external dependencies, making traces particularly attractive for large deployments.

Unfortunately limitations in the trace implementation prevent widespread use.

For example, the process of analyzing execution traces scales poorly with the size of the trace. Traces need to be parsed in their entirety to do anything useful with them, making them impossible to stream. As a result, trace parsing and validation has very high memory requirements for large traces.

Also, Go execution traces are designed to be internally consistent, but don't provide any way to align with other kinds of traces, for example OpenTelemetry traces and Linux sched traces. Alignment with higher level tracing mechanisms is critical to connecting business-level tasks with resource costs. Meanwhile alignment with lower level traces enables a fully vertical view of application performance to root out the most difficult and subtle issues.

Thanks to work in Go 1.21 cycle, the execution tracer's run-time overhead was reduced from about -10% throughput and +10% request latency in web services to about 1% in both for most applications. This reduced overhead in conjunction with making traces more scalable enables some exciting and powerful new opportunities for the diagnostic.

Lastly, the implementation of the execution tracer has evolved organically over time and it shows. The codebase also has many old warts and some age-old bugs that make collecting traces difficult, and seem broken. Furthermore, many significant decision decisions were made over the years but weren't thoroughly documented; those decisions largely exist solely in old commit messages and breadcrumbs left in comments within the codebase itself.

§ Goals

The goal of this document is to define an alternative implementation for Go execution traces that scales up to large Go deployments.

Specifically, the design presented aims to achieve:

• Make trace parsing require a small fraction of the memory it requires today.
• Streamable traces, to enable analysis without storage.
• Fix age-old bugs and present a path to clean up the implementation.

Furthermore, this document will present the existing state of the tracer in detail and explain why it's like that to justify the changes being made.

§ Design

Overview

The design is broken down into four parts:

• Timestamps and sequencing.
• Orienting against threads instead of Ps.
• Partitioning.
• Wire format cleanup.

These four parts are roughly ordered by how fundamental they are to the trace design, and so the former sections are more like concrete proposals, while the latter sections are more like design suggestions that would benefit from prototyping. The earlier parts can also be implemented without considering the latter parts.

Each section includes in the history and design of the existing system as well to document the current system in one place, and to more easily compare it to the new proposed system. That requires, however, a lot of prose, which can obscure the bigger picture. Here are the highlights of each section without that additional context.

Timestamps and sequencing.

• Compute timestamps from the OS's monotonic clock (nanotime).
• Use per-goroutine sequence numbers for establishing a partial order of events (as before).

Orienting against threads (Ms) instead of Ps.

• Batch trace events by M instead of by P.
• Use lightweight M synchronization for trace start and stop.
• Simplify syscall handling.
• All syscalls have a full duration in the trace.

Partitioning.

• Traces are sequences of fully self-contained partitions that may be streamed.
  • Each partition has its own stack table and string table.
• Partitions are purely logical: consecutive batches with the same ID.
  • In general, parsers need state from the previous partition to get accurate timing information.
  • Partitions have an "earliest possible" timestamp to allow for imprecise analysis without a previous partition.
• Partitions are bound by both a maximum wall time and a maximum size (determined empirically).
• Traces contain an optional footer delineating partition boundaries as byte offsets.
• Emit batch lengths to allow for rapidly identifying all batches within a partition.

Wire format cleanup.

• More consistent naming scheme for event types.
• Separate out "reasons" that a goroutine can block or stop from the event types.
• Put trace stacks, strings, and CPU samples in dedicated batches.

Timestamps and sequencing

For years, the Go execution tracer has used the cputicks runtime function for obtaining a timestamp. On most platforms, this function queries the CPU for a tick count with a single instruction. (Intuitively a "tick" goes by roughly every CPU clock period, but in practice this clock usually has a constant rate that's independent of CPU frequency entirely.) Originally, the execution tracer used this stamp exclusively for ordering trace events. Unfortunately, many modern CPUs don't provide such a clock that is stable across CPU cores, meaning even though cores might synchronize with one another, the clock read-out on each CPU is not guaranteed to be ordered in the same direction as that synchronization. This led to traces with inconsistent timestamps.

To combat this, the execution tracer was modified to use a global sequence counter that was incremented synchronously for each event. Each event would then have a sequence number that could be used to order it relative to other events on other CPUs, and the timestamps could just be used solely as a measure of duration on the same CPU. However, this approach led to tremendous overheads, especially on multiprocessor systems.

That's why in Go 1.7 the implementation changed so that each goroutine had its own sequence counter. The implementation also cleverly avoids including the sequence number in the vast majority of events by observing that running goroutines can't actually be taken off their thread until they're synchronously preempted or yield themselves. Any event emitted while the goroutine is running is trivially ordered after the start. The only non-trivial ordering cases left are where an event is emitted by or on behalf of a goroutine that is not actively running (Note: I like to summarize this case as "emitting events at a distance" because the scheduling resource itself is not emitting the event bound to it.) These cases need to be able to be ordered with respect to each other and with a goroutine starting to run (i.e. the GoStart event). In the current trace format, there are only two such cases: the GoUnblock event, which indicates that a blocked goroutine may start running again and is useful for identifying scheduling latencies, and GoSysExit, which is used to determine the duration of a syscall but may be emitted from a different P than the one the syscall was originally made on. (For more details on the GoSysExit case see in the next section.) Furthermore, there are versions of the GoStart, GoUnblock, and GoSysExit events that omit a sequence number to save space if the goroutine just ran on the same P as the last event, since that's also a case where the events are trivially serialized. In the end, this approach successfully reduced the trace overhead from over 3x to 10-20%.

However, it turns out that the trace parser still requires timestamps to be in order, leading to the infamous "time stamps out of order" error when cputicks inevitably doesn't actually emit timestamps in order. Ps are a purely virtual resource; they don't actually map down directly to physical CPU cores at all, so it's not even reasonable to assume that the same P runs on the same CPU for any length of time.

Although we can work around this issue, I propose we try to rely on the operating system's clock instead and fix up timestamps as a fallback. The main motivation behind this change is alignment with other tracing systems. It's already difficult enough to try to internally align the cputicks clock, but making it work with clocks used by other traces such as those produced by distributed tracing systems is even more difficult.

On Linux, the clock_gettime syscall, called nanotime in the runtime, takes around 15ns on average when called in a loop. This is compared to cputicks' 10ns. Trivially replacing all cputicks calls in the current tracer with nanotime reveals a small performance difference that depends largely on the granularity of each result. Today, cputicks' is divided by 64. On a 3 GHz processor, this amounts to a granularity of about 20 ns. Replacing that with nanotime and no time division (i.e. nanosecond granularity) results in a 0.22% geomean regression in throughput in the Sweet benchmarks. The trace size also increases by 17%. Dividing nanotime by 64 we see approximately no regression and a trace size decrease of 1.7%. Overall, there seems to be little performance downside to using nanotime, provided we pick an appropriate timing granularity: what we lose by calling nanotime, we can easily regain by sacrificing a small amount of precision. And it's likely that most of the precision below 128 nanoseconds or so is noise, given the average cost of a single call into the Go scheduler (~250 nanoseconds). To give us plenty of precision, I propose a target timestamp granularity of 64 nanoseconds. This should be plenty to give us fairly fine-grained insights into Go program behavior while also keeping timestamps small.

As for sequencing, I believe we must retain the per-goroutine sequence number design as-is. Relying solely on a timestamp, even a good one, has significant drawbacks. For one, issues arise when timestamps are identical: the parser needs to decide on a valid ordering and has no choice but to consider every possible ordering of those events without additional information. While such a case is unlikely with nanosecond-level timestamp granularity, it totally precludes making timestamp granularity more coarse, as suggested in the previous paragraph. A sequencing system that's independent of the system's clock also retains the ability of the tracing system to function despite a broken clock (modulo returning an error when timestamps are out of order, which again I think we should just work around). Even clock_gettime might be broken on some machines!

How would a tracing system continue to function despite a broken clock? For that I propose making the trace parser fix up timestamps that don't line up with the partial order. The basic idea is that if the parser discovers a partial order edge between two events A and B, and A's timestamp is later than B's, then the parser applies A's timestamp to B. B's new timestamp is in turn propagated later on in the algorithm in case another partial order edge is discovered between B and some other event C, and those events' timestamps are also out-of-order.

There's one last issue with timestamps here on platforms for which the runtime doesn't have an efficient nanosecond-precision clock at all, like Windows. (Ideally, we'd make use of system calls to obtain a higher-precision clock, like QPC, but calls to this API can take upwards of a hundred nanoseconds on modern hardware, and even then the resolution is on the order of a few hundred nanoseconds.) On Windows we can just continue to use cputicks to get the precision and rely on the timestamp fixup logic in the parser, at the cost of being unable to reliably align traces with other diagnostic data that uses the system clock.

Orienting by threads (Ms) instead of Ps

Today the Go runtime batches trace events by P. That is, trace events are grouped in batches that all happened, in order, on the same P. A batch is represented in the runtime as a buffer, 32 KiB in size, which is attached to a P when it's actively being written to. Events are written to this P's buffer in their encoded form. This design choice allows most event writes to elide synchronization with the rest of the runtime and linearizes the trace with respect to a P, which is crucial to sequencing without requiring a global total order.

Batching traces by any core scheduling resource (G, M, or P) could in principle have similar properties. At a glance, there are a few reasons Ps make a better choice. One reason is that there are generally a small number of Ps compared to Ms and Gs, minimizing the maximum number of buffers that can be active at any given time. Another reason is convenience. When batching, tracing generally requires some kind of synchronization with all instances of its companion resource type to get a consistent trace. (Think of a buffer which has events written to it very infrequently. It needs to be flushed at some point before the trace can be considered complete, because it may contain critical information needed to sequence events in other buffers.) Furthermore, synchronization when starting a trace is also generally useful, as that provides an opportunity to inspect the state of the world and write down details about it, simplifying validation. Stopping the world is a convenient way to get the attention of all Ps in the Go runtime.

However, there are problems with batching by P that make traces more complex than necessary.

The core of these problems lies with the GoSysExit event. This event requires special arrangements in both the runtime and when validating traces to ensure a consistent trace. The difficulty with this event is that it's emitted by a goroutine that was blocked in a syscall and lost its P, and because it doesn't have a P, it might race with the runtime enabling and disabling tracing. Therefore it needs to wait until it has a P to avoid that race. (Note: the tracing system does have a place to put events when there is no P available, but that doesn't help in this case. The tracing system uses the fact that it stops-the-world to synchronize with GoSysExit by preventing it from writing an event until the trace system can finish initialization.)

The problem with GoSysExit stems from a fundamental mismatch: Ms emit events, but only Ps are preemptible by the Go scheduler. This really extends to any situation where we'd like an M to emit an event when it doesn't have a P, say for example when it goes to sleep after dropping its P and not finding any work in the scheduler, and it's one reason why we don't have any M-specific events at all today.

So, suppose we batch trace events by M instead.

In the case of GoSysExit, it would always be valid to write to a trace buffer, because any synchronization would have to happen on the M instead of the P, so no races with stopping the world. However, this also means the tracer can't simply stop the world, because stopping the world is built around stopping user Go code, which runs with a P. So, the tracer would have to use something else (more on this later).

Although GoSysExit is simpler, GoSysBlock becomes slightly more complex in the case where the P is retaken by sysmon. In the per-P world it could be written into the buffer of the taken P, so it didn't need any synchronization. In the per-M world, it becomes an event that happens "at a distance" and so needs a sequence number from the syscalling goroutine for the trace consumer to establish a partial order.

However, we can do better by reformulating the syscall events altogether.

Firstly, I propose always emitting the full time range for each syscall. This is a quality-of-life choice that may increase trace overheads slightly, but also provides substantially more insight into how much time is spent in syscalls. Syscalls already take ~250 nanoseconds at a baseline on Linux and are unlikely to get faster in the future for security reasons (due to Spectre and Meltdown) and the additional event would never contain a stack trace, so writing it out should be quite fast. (Nonetheless, we may want to reconsider emitting these events for cgo calls.) The new events would be called, for example, GoSyscallBegin and GoSyscallEnd. If a syscall blocks, GoSyscallEnd is replaced with GoSyscallEndBlocked (more on this later).

Secondly, I propose adding an explicit event for stealing a P. In the per-M world, keeping just GoSysBlock to represent both a goroutine's state transition and the state of a P is not feasible, because we're revealing the fact that fundamentally two threads are racing with one another on the syscall exit. An explicit P-stealing event, for example ProcSteal, would be required to be ordered against a GoSyscallEndBlocked, with the former always happening before. The precise semantics of the ProcSteal event would be a ProcStop but one performed by another thread. Because this means events can now happen to P "at a distance," the ProcStart, ProcStop, and ProcSteal events all need sequence numbers.

Note that the naive emission of ProcSteal and GoSyscallEndBlocked will cause them to race, but the interaction of the two represents an explicit synchronization within the runtime, so the parser can always safely wait for the ProcSteal to emerge in the frontier before proceeding. The timestamp order may also not be right, but since we already committed to fixing broken timestamps in general, this skew will be fixed up by that mechanism for presentation. (In practice, I expect the skew to be quite small, since it only happens if the retaking of a P races with a syscall exit.)

Per-M batching might also incur a higher memory cost for tracing, since there are generally more Ms than Ps. I suspect this isn't actually too big of an issue since the number of Ms is usually close to the number of Ps. In the worst case, there may be as many Ms as Gs! However, if we also partition the trace, then the number of active buffers will only be proportional to the number of Ms that actually ran in a given time window, which is unlikely to be an issue. Still, if this does become a problem, a reasonable mitigation would be to simply shrink the size of each trace buffer compared to today. The overhead of the tracing slow path is vanishingly small, so doubling its frequency would likely not incur a meaningful compute cost.

Other than those three details, per-M batching should function identically to the current per-P batching: trace events may already be safely emitted without a P (modulo GoSysExit synchronization), so we're not losing anything else with the change.

Instead, however, what we gain is a deeper insight into thread execution. Thread information is currently present in execution traces, but difficult to interpret because it's always tied to P start and stop events. A switch to per-M batching forces traces to treat Ps and Ms orthogonally.

Given all this, I propose