Gotraceui—the manual

It is possible to add your own information to traces by using user annotations, which encompass log messages, regions, and tasks.

Log messages show up as events in Gotraceui, consist of a category and message, and can be emitted via Log or Logf.

Regions group events in a goroutine. They can be used to, for example, denote distinct steps when handling an API request, such as querying the database, processing the results, and serializing them. Regions can also be nested, for additional detail. They can be started with StartRegion and stopped with (*Region).End. It is important that regions are stopped in a LIFO order to maintain valid nesting. It is therefore recommended to use defer, like in the following example:

defer trace.StartRegion(ctx, "myTracedRegion").End()

There is also a helper function called WithRegion that wraps the execution of a function in a region.

Finally, tasks exist to group work that is happening across multiple goroutines. For example, if an incoming API request causes multiple goroutines to do work on behalf of that request in parallel, a task will be able to tie all of them together. Tasks are created similarly to regions, but with NewTask and (*Task).End respectively.

Gotraceui does not currently display tasks.

The top of the timelines view shows the axis. The bold tick indicates the origin of the axis and displays the absolute time at that point in the trace. Ticks to the left and right of the origin show relative decrements and increments to this absolute time.

By default, the origin is placed at the center of the axis, as analyzing traces often involves looking at what happened before and after an event. The origin can be moved by clicking and dragging anywhere on the axis. Alternatively, the context menu of the axis allows quickly placing the origin at the beginning, middle, or end of the axis. Manually placed origins will stay in place when resizing the window or timelines view, while origins set via the context menu will stay at their relative position.

Additionally, the axis contains red and purple sections, which correspond to the garbage collector’s stop-the-world phase and general activity. Pressing O cycles through displaying the red section, both sections, or none of the sections across the entire view.

The axis is followed by the memory plot, which shows memory usage (more specifically the size of the heap) and the garbage collector goal, using green and purple respectively. Hovering anywhere on the plot will show a tooltip with the exact numeric values. The memory plot is separated from the timelines by a black border. This border can be dragged to resize the plot.

The plot’s context menu offers the following additional features:

Hide/Show legends

hides or shows the labels for the minimum and maximum value.

Hide/Show "Heap size" series

hides or shows the heap size.

Hide/Show "Heap goal" series

hides or shows the heap goal.

Set extents to global extrema

scales the plot so that the bottom represents the smallest measured value and the top represents the largest measured value, for the entire trace. Only the values of enabled series will be considered.

Set extents to local extrema

works like the previous command, but only considers the currently visible portion of the trace.

Auto-set extents to local extrema

automatically applies the previous command whenever the currently visible portion of the trace changes.

Reset extents

resets the extents to their default: zero at the bottom and the global maximum at the top. It also disables auto-set extents.

The main section of the timelines view consists of a number of horizontally stacked timelines. A timeline might show a processor, a goroutine, or phases of the garbage collector. Every timeline has a label, hovering over which may display a tooltip, and right-clicking which may open a context menu.

For example, for processors, the tooltip will show how much time was spent executing user code, doing garbage collection work, and being idle. Pressing Ctrl/⌘ + LMB on a label will zoom the view such that all spans in that timeline are visible. Pressing LMB on a goroutine label will open a panel with additional information about the goroutine (see 5.3 for more on panels.)

A timeline consists of one or more horizontally stacked tracks and each track consists of a series of spans. A span represents a state for some duration of time. For example, a goroutine may be blocked on a channel send operation for 100 ms, and this would be displayed as a single span. Tracks can visualize various things, such as the states of goroutines, call stacks, or user regions.

The space before the first and after the last span in a track is filled with whiskers, which are green and grey respectively. To differentiate goroutines that ended during the trace from goroutines that were still running by the end of the trace, the tracks of goroutines that have ended have a final, black span, indicating the end of the goroutine.

The view can be moved around by dragging with LMB, by using the scroll wheel, or by using the scrollbar. Holding Ctrl/⌘ while scrolling zooms in and out, centered around the cursor’s position. Holding Shift while scrolling swaps the axes. That is, scrolling vertically will scroll horizontally and vice versa. Dragging with Ctrl/⌘ + LMB selects a region of time to zoom to.

The Display menu contains commands for changing the way timelines are displayed, as well as commands for quick navigation.

Hovering over a span will show context-specific information about it, including its state and duration, but also additional information such as tags (see 5.1.3.2) or the reason for being in a certain state. Pressing LMB on a span will open a panel with additional information about the span, including a list of events that happened during that span. Pressing Ctrl/⌘ + LMB on a span will zoom to the span.

Spans have different colors depending on the states they represent. Different kinds of timelines and tracks use different color schemes. These are explained in 5.1.3.1.

Depending on the zoom level, individual spans may be too small to display. When that happens, Gotraceui groups small spans together in a merged span, which is rendered using a downsampled preview of the contained spans. Zooming into merged spans will progressively show higher resolution previews, until eventually the merged spans break up into individual spans.

Computing the previews for merged spans can sometimes take a long time, in which case we fall back to lower quality previews or a placeholder while the better preview gets computed in the background. As long as some of the visible previews aren’t displayed in the best quality possible, a dancing gopher will be shown.

All spans have context menus, which include at least a Zoom option, which acts identically to Ctrl/⌘ + LMB, and a Show span info option, which opens the span panel. Some spans have more options:

• Spans in processor timelines have a Scroll to goroutine option to scroll to the corresponding goroutine timeline.
• Blocked spans in goroutine timelines have a Scroll to unblocking goroutine option to scroll to the goroutine that unblocked the goroutine. For example, for a goroutine stuck in a channel receive, this will scroll to the sending goroutine.
• Running spans in goroutine timelines have a Scroll to processor option to scroll to the processor that the goroutine is running on at the time.

Clicking on goroutine labels or goroutine links opens the goroutine panel.

Goroutine panels display the following information:

• Basic information, such as the goroutine’s parent, its duration, or what function it was running.
• Statistics of the different states of spans.
• All spans in the goroutine.
• All events in the goroutine.
• The stack trace, showing where the goroutine was created, if that information is available.

Goroutine panels have two additional buttons for scrolling and zooming to the goroutine.

Clicking on spans (either merged or unmerged ones) opens the span panel.

Span panels display the following information:

• Basic information, such as the start and end time.
• Statistics of the different states.
• A list of the individual spans.
• For goroutine spans, including user regions, events that occurred during the span.
• For unmerged spans, the stack trace.

Additionally, individual user region spans have a button labeled Select user region, which selects all user region spans with the same label. Spans selected that way have a Histogram tab, which displays a histogram of span durations. See 5.5 for more information on histograms.

Span panels have two additional buttons for scrolling & panning and zooming to the spans.

Clicking on function links—such as the ones displayed in goroutine panels—opens the function panel.

Function panels display the following information:

• Basic information, such as how many goroutines ran the function
• A list of all goroutines.
• A histogram, showing the durations of goroutines that ran the function. See 5.5 for more information on using histograms.

The Goroutines tab displays a tabular view of all goroutines in the trace.

Gotraceui can display processor utilization using quantized heatmaps. These can be accessed via Analyze > Open processor utilization heatmap.

The X-axis shows time, the Y-axis shows utilization in percent, and color saturation represents the number of processors.

The size of a bucket can be adjusted using the arrow keys. The ← and → keys decrease and increase the amount of time represented by a bucket in steps of 10 ms. The ↓ and ↑ keys decrease and increase the range of percentage points per bucket.

By default, a ranked color palette is used, where each distinct value that occurred gets its own saturation. Compared to a linear palette, where the color is proportional to the value, a ranked palette makes it easier to spot outliers. On the flip side, a linear palette allows comparing absolute values just by looking at the color.

The bottom of the heatmap tab displays information about the currently hovered bucket: the range of time and the range of utilization represented by the bucket, as well as the number of processors in said bucket.

Please note that processor refers to the concept from the Go runtime, and not actual CPUs or CPU cores. While processor utilization is a good estimate for actual CPU utilization, it cannot account for the OS scheduler, nor for cgo.

Gotraceui can display flame graphs based on CPU sampling as well as the stack traces associated with tracing events.

Flame graphs are a visualization of hierarchical data, created to visualize stack traces of profiled software so that the most frequent code-paths to be identified quickly and accurately. —Brendan Gregg

Our flame graphs follow the common conventions: colors don’t have any meaning and only serve to differentiate spans, and the order of spans on the X axis is alphabetical. Gotraceui assigns colors so that functions from the same package have the same hue, using different lightness values to differentiate neighboring spans.

There are two ways of opening flame graphs: the first is by using Analyze > Open flame graph. This will open a flame graph visualizing all of the CPU samples found in the trace. The second is by choosing the Open flame graph option in goroutine context menus. This will open a flame graph specific to that goroutine, displaying both CPU samples (under the root span titled Running) and stacks from goroutine state transitions (e.g. being blocked on a channel send), thus showing both on- and off-CPU time.

Flame graphs are interactive. Hovering over spans will display tooltips with useful information. Pressing Ctrl/⌘ + LMB on a span will zoom to it and Ctrl/⌘ + Z undoes zooming.

The scheduler manages three resources: Machines, Processors, and Goroutines. In conversations, documentation, and source code these are usually referred to by their initials.

Machines correspond to operating system threads. They are responsible for actually executing instructions. Processors are, conceptually, tokens. Machines need to hold processors to be allowed to run goroutines. This serves two purposes: First, it puts a bound on parallelism. You wouldn’t want hundreds of threads to fight for CPU resources. Second, it allows for an efficient implementation. While processors are tokens in principle, they are also a concrete data structure that holds information necessary for efficiently running goroutines. In other words, machines use processors to run goroutines. The environment variable GOMAXPROCS controls the number of available processors. It defaults to the number of CPU cores.

In the context of execution traces and Gotraceui, goroutines are said to be running on processors, as the trace format is processor-centric. In fact, Gotraceui does not expose machines at all. If it did, it would show goroutines running on processors and processors running on machines.

If you’d like to learn more about the internals of the scheduler that aren’t necessary to understand traces but are nevertheless interesting, check out Daniel Morsing’s blog post on the topic.

Syscalls, short for system calls, are the primary way that processes use to communicate with the operating system’s kernel. They are used to, for example, manipulate files, spawn new processes, use the network, etc.

Syscalls are synchronous: once a thread executes a syscall it cannot do anything else until the syscall returns. When a goroutine executes a syscall it causes the whole machine to block—that machine will not be able to run any other goroutines until the syscall returns. When this happens, the machine loses its processor, after all it is no longer able to run goroutines, and another machine may pick up the processor. Additionally, Go ensures that there are always enough unblocked machines to run all processors by creating new ones when necessary.

All of this work is fairly expensive. That is why Go differentiates between ``non-blocking’’ and ``blocking’’ syscalls. Non-blocking syscalls aren’t truly non-blocking; they’re just syscalls that return very quickly. For example, the gettimeofday syscall usually returns within a few microseconds. It would take longer to give up the processor and spawn a new thread than it would to wait for the syscall to return. Additionally, the goroutine that invoked the syscall would have to wait its turn to be scheduled again, which might involve waiting for another goroutine to be preempted. All in all, the cost of a cheap syscall would multiply tenfold. Instead of doing all that, Go just waits to see if the syscall returns promptly. Only if it doesn’t will Go go through the steps we described earlier.

In the execution trace, and thus Gotraceui, these two kinds of syscalls are represented differently. Short syscalls appear as instantaneous events during a span, while long syscalls appear as their own spans.

By default, the scheduler moves goroutines between processors and processors between machines as necessary to maintain good performance. For most Go programs, this is fine and indeed desirable. However, when using cgo, it may be the case that the libraries you use depend on thread-local storage (TLS). TLS allows storing per-thread state, which is little more than global variables scoped to threads. Of course, if Go moves goroutines across threads, then thread-local state will not be available consistently. To solve this problem, Go offers the runtime.LockOSThread function, which locks the current goroutine to the current thread. From that point on, the goroutine will only ever run on that thread (unless UnlockOSThread is called), and no other goroutines will be allowed to run on it.

Because Gotraceui visualizes processors and goroutines but not machines, the use of LockOSThread is largely invisible. In particular, thread-locked goroutines can still move between processors freely.

All goroutines are in one of three states: Runnable, running, and blocked. The runtime subdivides blocked into different reasons for being blocked, and Gotraceui introduces some of its own subdivisions to further increase the level of detail.

The following is an exhaustive list of states found in Gotraceui. Each state name’s background color corresponds to the span color used in Gotraceui.

created

Newly created goroutines will be in this state before they get scheduled for the first time. It is a special case of the ready state.

active

Active goroutines are those that are currently running.

send, recv, select

These states describe the three ways in which goroutines can be blocked on channel communication.

sync

This state is used by goroutines that are blocked on sync primitives, such as sync.Mutex.

sync.Once

Blocked on a sync.Once. This is a special case of the sync state and detected by Gotraceui based on stack traces.

sync.Cond

Blocked on a condition variable (sync.Cond.)

I/O

This state is entered by goroutines that are waiting for pollable I/O to complete. See 6.2 for more information.

syscall

Goroutines enter this state when they invoke a blocking syscall. See 6.1.2 for an explanation of the difference between blocking and non-blocking syscalls in the context of Go.

blocked

Blocked goroutines are waiting for something to happen, but we don’t know what. This usually happens for goroutines of the runtime that don’t emit more accurate information. User goroutines will usually have more specific states such as send.

inactive

This state is one of Gotraceui’s custom states and is used for goroutines that are blocked or ready to run, but aren’t actually eager to run. For blocked goroutines, this is exclusively used by goroutines of the runtime that block on some lock to pace the amount of work they do. Goroutines that are technically in the ready state but are marked inactive are those that called runtime.Gosched or time.Sleep, as this indicates that they willingly gave up part of their share in CPU time, and their time spent waiting shouldn’t be considered scheduler latency.

Blocked (GC)

The goroutine is waiting to assist the garbage collector.

ready

A goroutine in this state isn’t blocked on anything anymore and can start running as soon as it gets scheduled. A goroutine can be in this state because there aren’t any free processors to run it, or simply because the scheduler hasn’t gotten around to starting it yet. Goroutines can transition into this state from the active state if they get preempted, or from any of the various blocked states once they get unblocked. Time spent in this state is commonly called scheduler latency.

GC (idle)

A runtime.gcBgMarkWorker goroutine doing idle mark work.

GC (dedicated)

A runtime.gcBgMarkWorker goroutine doing dedicated mark work.

GC (fractional)

A runtime.gcBgMarkWorker goroutine doing fractional mark work.

GC mark assist

Goroutines in the GC mark assist state are assisting the mark phase.

GC sweep

Goroutines in the GC sweep state are sweeping memory.

stuck

Goroutines in this state are stuck and can never make progress. This happens, for example, when receiving from a nil channel or using select with no cases.

done

This state is used for synthetic spans that indicate that goroutines have exited.