Skip to content

Commit be0b2a3

Browse files
adonovanadonovan
committed
cmd/trace: add basic documentation to main page
This change adds rudimentary explanation of the various visualizations to main page of the trace server. There is clearly a vast amount one could write here, especially in the form of tutorials, but I've tried to restrict it to just basic conceptual overview. Change-Id: Id4dfe9d47f9b31ed5f8fe39f8b3a7c60c0ae8d5a Reviewed-on: https://go-review.googlesource.com/c/go/+/412876 Reviewed-by: Michael Pratt <[email protected]> Run-TryBot: Alan Donovan <[email protected]> TryBot-Result: Gopher Robot <[email protected]>
1 parent b004c73 commit be0b2a3

File tree

1 file changed

+183
-11
lines changed

1 file changed

+183
-11
lines changed

‎src/cmd/trace/main.go‎

Lines changed: 183 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -185,23 +185,195 @@ func httpMain(w http.ResponseWriter, r *http.Request) {
185185

186186
var templMain = template.Must(template.New("").Parse(`
187187
<html>
188+
<style>
189+
/* See https://github.com/golang/pkgsite/blob/master/static/shared/typography/typography.css */
190+
body {
191+
font-family: -apple-system, BlinkMacSystemFont, 'Segoe UI', Helvetica, Arial, sans-serif, 'Apple Color Emoji', 'Segoe UI Emoji';
192+
font-size: 1rem;
193+
line-height: normal;
194+
max-width: 9in;
195+
margin: 1em;
196+
}
197+
h1 { font-size: 1.5rem; }
198+
h2 { font-size: 1.375rem; }
199+
h1,h2 {
200+
font-weight: 600;
201+
line-height: 1.25em;
202+
word-break: break-word;
203+
}
204+
p { color: grey85; font-size:85%; }
205+
</style>
188206
<body>
207+
<h1>cmd/trace: the Go trace event viewer</h1>
208+
<p>
209+
This web server provides various visualizations of an event log gathered during
210+
the execution of a Go program that uses the <a href='https://pkg.go.dev/runtime/trace'>runtime/trace</a> package.
211+
</p>
212+
213+
<h2>Event timelines for running goroutines</h2>
189214
{{if $}}
215+
<p>
216+
Large traces are split into multiple sections of equal data size
217+
(not duration) to avoid overwhelming the visualizer.
218+
</p>
219+
<ul>
190220
{{range $e := $}}
191-
<a href="{{$e.URL}}">View trace ({{$e.Name}})</a><br>
221+
<li><a href="{{$e.URL}}">View trace ({{$e.Name}})</a></li>
192222
{{end}}
193-
<br>
223+
</ul>
194224
{{else}}
195-
<a href="/trace">View trace</a><br>
225+
<ul>
226+
<li><a href="/trace">View trace</a></li>
227+
</ul>
196228
{{end}}
197-
<a href="/goroutines">Goroutine analysis</a><br>
198-
<a href="/io">Network blocking profile</a> (<a href="/io?raw=1" download="io.profile">⬇</a>)<br>
199-
<a href="/block">Synchronization blocking profile</a> (<a href="/block?raw=1" download="block.profile">⬇</a>)<br>
200-
<a href="/syscall">Syscall blocking profile</a> (<a href="/syscall?raw=1" download="syscall.profile">⬇</a>)<br>
201-
<a href="/sched">Scheduler latency profile</a> (<a href="/sche?raw=1" download="sched.profile">⬇</a>)<br>
202-
<a href="/usertasks">User-defined tasks</a><br>
203-
<a href="/userregions">User-defined regions</a><br>
204-
<a href="/mmu">Minimum mutator utilization</a><br>
229+
<p>
230+
This view displays a timeline for each of the GOMAXPROCS logical
231+
processors, showing which goroutine (if any) was running on that
232+
logical processor at each moment.
233+
234+
Each goroutine has an identifying number (e.g. G123), main function,
235+
and color.
236+
237+
A colored bar represents an uninterrupted span of execution.
238+
239+
Execution of a goroutine may migrate from one logical processor to another,
240+
causing a single colored bar to be horizontally continuous but
241+
vertically displaced.
242+
</p>
243+
<p>
244+
Clicking on a span reveals information about it, such as its
245+
duration, its causal predecessors and successors, and the stack trace
246+
at the final moment when it yielded the logical processor, for example
247+
because it made a system call or tried to acquire a mutex.
248+
249+
Directly underneath each bar, a smaller bar or more commonly a fine
250+
vertical line indicates an event occuring during its execution.
251+
Some of these are related to garbage collection; most indicate that
252+
a goroutine yielded its logical processor but then immediately resumed execution
253+
on the same logical processor. Clicking on the event displays the stack trace
254+
at the moment it occurred.
255+
</p>
256+
<p>
257+
The causal relationships between spans of goroutine execution
258+
can be displayed by clicking the Flow Events button at the top.
259+
</p>
260+
<p>
261+
At the top ("STATS"), there are three additional timelines that
262+
display statistical information.
263+
264+
"Goroutines" is a time series of the count of existing goroutines;
265+
clicking on it displays their breakdown by state at that moment:
266+
running, runnable, or waiting.
267+
268+
"Heap" is a time series of the amount of heap memory allocated (in orange)
269+
and (in green) the allocation limit at which the next GC cycle will begin.
270+
271+
"Threads" shows the number of kernel threads in existence: there is
272+
always one kernel thread per logical processor, and additional threads
273+
are created for calls to non-Go code such as a system call or a
274+
function written in C.
275+
</p>
276+
<p>
277+
Above the event trace for the first logical processor are
278+
traces for various runtime-internal events.
279+
280+
The "GC" bar shows when the garbage collector is running, and in which stage.
281+
Garbage collection may temporarily affect all the logical processors
282+
and the other metrics.
283+
284+
The "Network", "Timers", and "Syscalls" traces indicate events in
285+
the runtime that cause goroutines to wake up.
286+
</p>
287+
<p>
288+
The visualization allows you to navigate events at scales ranging from several
289+
seconds to a handful of nanoseconds.
290+
291+
Consult the documentation for the Chromium <a href='https://www.chromium.org/developers/how-tos/trace-event-profiling-tool/'>Trace Event Profiling Tool<a/>
292+
for help navigating the view.
293+
</p>
294+
295+
<ul>
296+
<li><a href="/goroutines">Goroutine analysis</a></li>
297+
</ul>
298+
<p>
299+
This view displays information about each set of goroutines that
300+
shares the same main function.
301+
302+
Clicking on a main function shows links to the four types of
303+
blocking profile (see below) applied to that subset of goroutines.
304+
305+
It also shows a table of specific goroutine instances, with various
306+
execution statistics and a link to the event timeline for each one.
307+
308+
The timeline displays only the selected goroutine and any others it
309+
interacts with via block/unblock events. (The timeline is
310+
goroutine-oriented rather than logical processor-oriented.)
311+
</p>
312+
313+
<h2>Profiles</h2>
314+
<p>
315+
Each link below displays a global profile in zoomable graph form as
316+
produced by <a href='https://go.dev/blog/pprof'>pprof</a>'s "web" command.
317+
318+
In addition there is a link to download the profile for offline
319+
analysis with pprof.
320+
321+
All four profiles represent causes of delay that prevent a goroutine
322+
from running on a logical processor: because it was waiting for the network,
323+
for a synchronization operation on a mutex or channel, for a system call,
324+
or for a logical processor to become available.
325+
</p>
326+
<ul>
327+
<li><a href="/io">Network blocking profile</a> (<a href="/io?raw=1" download="io.profile">⬇</a>)</li>
328+
<li><a href="/block">Synchronization blocking profile</a> (<a href="/block?raw=1" download="block.profile">⬇</a>)</li>
329+
<li><a href="/syscall">Syscall blocking profile</a> (<a href="/syscall?raw=1" download="syscall.profile">⬇</a>)</li>
330+
<li><a href="/sched">Scheduler latency profile</a> (<a href="/sche?raw=1" download="sched.profile">⬇</a>)</li>
331+
</ul>
332+
333+
<h2>User-defined tasks and regions</h2>
334+
<p>
335+
The trace API allows a target program to annotate a <a
336+
href='https://pkg.go.dev/runtime/trace#Region'>region</a> of code
337+
within a goroutine, such as a key function, so that its performance
338+
can be analyzed.
339+
340+
<a href='https://pkg.go.dev/runtime/trace#Log'>Log events</a> may be
341+
associated with a region to record progress and relevant values.
342+
343+
The API also allows annotation of higher-level
344+
<a href='https://pkg.go.dev/runtime/trace#Task'>tasks</a>,
345+
which may involve work across many goroutines.
346+
</p>
347+
<p>
348+
The links below display, for each region and task, a histogram of its execution times.
349+
350+
Each histogram bucket contains a sample trace that records the
351+
sequence of events such as goroutine creations, log events, and
352+
subregion start/end times.
353+
354+
For each task, you can click through to a logical-processor or
355+
goroutine-oriented view showing the tasks and regions on the
356+
timeline.
357+
358+
Such information may help uncover which steps in a region are
359+
unexpectedly slow, or reveal relationships between the data values
360+
logged in a request and its running time.
361+
</p>
362+
<ul>
363+
<li><a href="/usertasks">User-defined tasks</a></li>
364+
<li><a href="/userregions">User-defined regions</a></li>
365+
</ul>
366+
367+
<h2>Garbage collection metrics</h2>
368+
<ul>
369+
<li><a href="/mmu">Minimum mutator utilization</a></li>
370+
</ul>
371+
<p>
372+
This chart indicates the maximum GC pause time (the largest x value
373+
for which y is zero), and more generally, the fraction of time that
374+
the processors are available to application goroutines ("mutators"),
375+
for any time window of a specified size, in the worst case.
376+
</p>
205377
</body>
206378
</html>
207379
`))

0 commit comments

Comments
 (0)