The task-oriented trace view presents the execution trace organized
based on goroutines. Often, which P a goroutine was running on is
useful, so this CL includes the P ids in the goroutine execution slices.
R=go1.11
Change-Id: I96539bf8215e5c1cd8cc997a90204f57347c48c8
Reviewed-on: https://go-review.googlesource.com/90221
Reviewed-by: Heschi Kreinick <heschi@google.com>
The GC time for a task is defined by the sum of GC duration
overlapping with the task's duration.
Also, grey out non-overlapping slices in the task-oriented
trace view.
R=go1.11
Change-Id: I42def0eb520f5d9bd07edd265e558706f6fab552
Reviewed-on: https://go-review.googlesource.com/90219
Reviewed-by: Heschi Kreinick <heschi@google.com>
This adds the ability to add a #x:y anchor to the trace view URL that
causes the viewer to initially select from x ms to y ms.
Change-Id: I4a980d8128ecc85dbe41f224e8ae336707a4eaab
Reviewed-on: https://go-review.googlesource.com/60794
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
golang.org/cl/81315 attempted to distinguish system goroutines
by examining the function name in the goroutine stack. It assumes that
the information would be available when GoSysBlock or GoInSyscall
events are processed, but it turned out the stack information is
set too late (when the goroutine gets a chance to run).
This change initializes the goroutine information entry when
processing GoCreate event which should be one of the very first
events for the every goroutine in trace.
Fixes#22574
Change-Id: I1ed37087ce2e78ed27c9b419b7d942eb4140cc69
Reviewed-on: https://go-review.googlesource.com/83595
Reviewed-by: Austin Clements <austin@google.com>
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
The number of threads in syscall presented by execution tracer's
trace view includes not only the threads calling system calls on behalf
of user created goroutines, but also those running on behalf of system
goroutines.
When the number of such system goroutines was small, the graph was
useful when examining where a program was saturating the CPU.
But as more and more system goroutines are invloved the graph became
less useful for the purpose - for example, after golang.org/cl/34784,
the timer goroutines dominate in the graph with large P
because the runtime creates per-P timer goroutines.
This change excludes the threads in syscall on behalf of runtime (system
goroutines) from the visualization. Alternatively, I could visualize the
count of such threads in a separate counter but in the same graph.
Given that many other debug endpoints (e.g. /debug/pprof/goroutine) hide
the system goroutines, including them in the same graph can confuse users.
Update #22574
Change-Id: If758cd6b9ed0596fde9a471e846b93246580b9d5
Reviewed-on: https://go-review.googlesource.com/81315
Reviewed-by: Austin Clements <austin@google.com>
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
The trace command computes IO, Schedule, Block, and Syscall profiles
by following the unblocking links in the execution trace and summing
up the duration. This change offers variations of those profiles
that include only selected goroutine types. The id parameter takes the
goroutine type - i.e. pc of the goroutine.
The output is available from the /goroutine view. So, users can see
where the goroutines of interest typically block.
Also, these profiles are available for download so users can use
pprof or other tools to interpret the output. This change adds links
for download of global profile in the main page.
Change-Id: I35699252056d164e60de282b0406caf96d629c85
Reviewed-on: https://go-review.googlesource.com/75710
Reviewed-by: Sameer Ajmani <sameer@golang.org>
CL 56950 correctly identified code with checks that were impossible.
But instead of correcting the checks it deleted them.
This CL corrects the code to check what was meant.
Change-Id: Ic89222184ee4fa5cacccae12d750601a9438ac8d
Reviewed-on: https://go-review.googlesource.com/78113
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
When traceviewer encounters a failure of json trace import
due to data error, onImportFail tried to access an error variable
which was not yet defined.
Change-Id: I431be03f179aafacaf1fd3c62a6337e8b5bd18fb
Reviewed-on: https://go-review.googlesource.com/71970
Reviewed-by: Austin Clements <austin@google.com>
In general, there are no guarantee that `go` command exist on $PATH.
This CL tries to get `go` command from $GOROOT/bin instead.
There are three kinds of code we should handle:
For normal code, the CL implements goCmd() or goCmdName().
For unit tests, the CL uses testenv.GoTool() or testenv.GoToolPath().
For integration tests, the CL sets PATH=$GOROOT/bin:$PATH in cmd/dist.
Note that make.bash sets PATH=$GOROOT/bin:$PATH in the build process.
So this change is only useful when we use toolchain manually.
Updates #21875
Change-Id: I963b9f22ea732dd735363ececde4cf94a5db5ca2
Reviewed-on: https://go-review.googlesource.com/64650
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Right now we only kind of sort of trace GC STW events. We emit events
around mark termination, but those start well after stopping the world
and end before starting it again, and we don't emit any events for
sweep termination.
Fix this by generalizing EvGCScanStart/EvGCScanDone. These were
already re-purposed to indicate mark termination (despite the names).
This commit renames them to EvGCSTWStart/EvGCSTWDone, adds an argument
to indicate the STW reason, and shuffles the runtime to generate them
right before stopping the world and right after starting the world,
respectively.
These events will make it possible to generate precise minimum mutator
utilization (MMU) graphs and could be useful in detecting
non-preemptible goroutines (e.g., #20792).
Change-Id: If95783f370781d8ef66addd94886028103a7c26f
Reviewed-on: https://go-review.googlesource.com/55411
Reviewed-by: Rick Hudson <rlh@golang.org>
This is useful when debugging the tool.
Some tweaks on logging: log the webserver address, log.Print instead
of log.Printf when possible.
Change-Id: Iaf71b6523b40dc13795511784d48eacf0f5a396a
Reviewed-on: https://go-review.googlesource.com/59570
Reviewed-by: Heschi Kreinick <heschi@google.com>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
Generated with
github.com/catapult/tracing/bin/vulcanize_trace_viewer
catapult @ ab4d571fa
Renamed trace_viewer_lean.html to trace_viewer_full.html
to make it clear we are using the full version of trace viewer
(waiting for https://github.com/catapult-project/catapult/issues/2247
to be fixed).
Update #15302
Change-Id: Ice808bb27ab79a1dec9fc863e0c5a761027ebfbe
Reviewed-on: https://go-review.googlesource.com/58750
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
All of these are uints of different sizes, so checking >= 0 or < 0 are
effectively no-ops.
Found with staticcheck.
Change-Id: I16ac900eb7007bc8f9018b302136d42e483a4180
Reviewed-on: https://go-review.googlesource.com/56950
Reviewed-by: Matt Layher <mdlayher@gmail.com>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Run-TryBot: Matt Layher <mdlayher@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Currently all trace slices get shifted to start at time 0. This makes
it very difficult to find specific points in time unless they fall in
the first slice.
For example, right now when you click "View trace
(6.005646218s-8.155419698s)" on the trace tool's main page, the trace
view puts the first event in that slice at time 0. If you're looking
for something that happened at time 7s, you have to look at time
0.9943537s in the trace view. And if you want to subtract times taken
from different slices, you have to figure out what those time really
correspond to.
Fix this by telling the trace viewer not to shift the times when it
imports the trace. In the above example, this makes the view of that
second trace slice start at time 6.005646218s, so you don't have to do
any gymnastics to find or calculate times in later slices.
Change-Id: I04e0afda60f5573fdd8ad96238c24013297ef263
Reviewed-on: https://go-review.googlesource.com/54633
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
This updates the HTML served for the trace viewer to follow the latest
revision of the example from the upstream tracing project.
The main thing this adds is CSS for the trace viewer (which was
actually in the example at the originally referenced revision, so I'm
not sure why it got dropped). In particular, this expands the trace
viewer to use the entire browser client area, which fixes several
problems with the current page:
1. The details pane gets cut off at a strange place and can get a
scroll bar even if there's plenty of room below it on the page. This
fixes the bottom of the details pane to the bottom of the window.
2. If the track view is very tall (lots of procs), there's no way to
view the top tracks and the details pane at the same time. This fixes
this problem by limiting the height of the track view to something
less than the height of the window so it gets a scroll bar of its own
if necessary.
3. Dragging the divider between the track pane and the details pane
actually moves the bottom of the details pane without moving the
divider. Fixing the height of the trace viewer fixes this problem.
Change-Id: Ia811e72a7413417ca21c45e932c9db2724974633
Reviewed-on: https://go-review.googlesource.com/54632
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
This displays the swept and reclaimed bytes for sweep events in the
lower panel of the trace viewer.
Change-Id: If1665a1c02bbc47700e0d9f515e574f013f3f285
Reviewed-on: https://go-review.googlesource.com/40812
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
There's no guarantee that all in-progress mark assists will finish
before the trace does. Don't crash if that happens.
I haven't added a test because there's quite a bit of ceremony involved
and the bug is fairly straightforward.
Change-Id: Ia1369a8e2260fc6a328ad204a1eab1063d2e2c90
Reviewed-on: https://go-review.googlesource.com/37540
Reviewed-by: Austin Clements <austin@google.com>
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
The tutorial ends without mentioning how to use the generated
pprof-like profile with the pprof tool. This may be very trivial
for users who are already very familiar with the Go tools, but
for the newcomers, it saves a lot of time to finalize the tutorial
with an example of `go tool pprof` invocation.
Change-Id: Idf034eb4bfb9672ef10190e66fcbf873e8f08f6a
Reviewed-on: https://go-review.googlesource.com/36803
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
During the mark phase of garbage collection, goroutines that allocate
may be recruited to assist. This change creates trace events for mark
assists and displays them similarly to sweep assists in the trace
viewer.
Mark assists are different than sweeps in that they can be preempted, so
displaying them in the trace viewer is a little tricky -- we may need to
synthesize multiple slices for one mark assist. This could have been
done in the parser instead, but I thought it might be preferable to keep
the parser as true to the event stream as possible.
Change-Id: I381dcb1027a187a354b1858537851fa68a620ea7
Reviewed-on: https://go-review.googlesource.com/36015
Run-TryBot: Heschi Kreinick <heschi@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Austin Clements <austin@google.com>
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes#17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
This allows both the runtime and the cmd/pprof code to use the package,
just like we do for internal/trace.
Change-Id: I7606977284e1def36c9647354c58e7c1e93dba6b
Reviewed-on: https://go-review.googlesource.com/32452
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Currently when a goroutine blocks on a GC assist, it emits a generic
EvGoBlock event. Since assist blocking events and, in particular, the
length of the blocked assist queue, are important for diagnosing GC
behavior, this commit adds a new EvGoBlockGC event for blocking on a
GC assist. The trace viewer uses this event to report a "waiting on
GC" count in the "Goroutines" row. This makes sense because, unlike
other blocked goroutines, these goroutines do have work to do, so
being blocked on a GC assist is quite similar to being in the
"runnable" state, which we also report in the trace viewer.
Change-Id: Ic21a326992606b121ea3d3d00110d8d1fdc7a5ef
Reviewed-on: https://go-review.googlesource.com/30704
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
Currently the trace tool tracks an overall counts of goroutine states,
but not the states of any individual goroutine. We're about to add
more sophisticated blocked-state tracking, so add this tracking and
base the state counts off the tracked goroutine states.
Change-Id: I943ed61782436cf9540f4ee26c5561715c5b4a1d
Reviewed-on: https://go-review.googlesource.com/30703
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
Currently mark workers are shown in the trace as regular goroutines
labeled "runtime.gcBgMarkWorker". That's somewhat unhelpful to an end
user because of the opaque label and particularly unhelpful to runtime
developers because it doesn't distinguish the different types of mark
workers.
Fix this by introducing a variant of the GoStart event called
GoStartLabel that lets the runtime indicate a label for a goroutine
execution span and using this to label mark worker executions as "GC
(<mode>)" in the trace viewer.
Since this bumps the trace version to 1.8, we also add test data for
1.7 traces.
Change-Id: Id7b9c0536508430c661ffb9e40e436f3901ca121
Reviewed-on: https://go-review.googlesource.com/30702
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
The trace tool can generate some interesting profiles, but it was only
exposing them as svg through the web UI. This adds command line options
to generate the raw pprof file.
Change-Id: I52e4f909fdca6f65c3616add444e3892783640f4
Reviewed-on: https://go-review.googlesource.com/23324
Reviewed-by: Russ Cox <rsc@golang.org>
When starting tracing, EvGoCreate events are added for existing
goroutines that may have been blocking in syscall. EvGoCreate
increments the runnable goroutine count. This change makes the
following EvGoInSyscall event decrement the runnable goroutine count
because we now know that goroutine is in syscall, and not runnable.
Made generateTrace return an error, at any given time, the number
of runnable/running/insyscall goroutines becomes non-negative.
Added a basic test that checks the number of runnable/running
goroutines don't include the goroutines in syscall - the test failed
before this change.
Change-Id: Ib732c382e7bd17158a437576f9d589ab89097ce6
Reviewed-on: https://go-review.googlesource.com/25552
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
Currently these are labeled "MARK", which was accurate in the STW
collector, but these really indicate mark termination now, since
marking happens for the full duration of the concurrent GC. Re-label
them as "MARK TERMINATION" to clarify this.
Change-Id: Ie98bd961195acde49598b4fa3f9e7d90d757c0a6
Reviewed-on: https://go-review.googlesource.com/30018
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
Currently, the process-wide GC state is attributed to the P that
happened to perform the allocation that exceeded the GC trigger. This
is pretty arbitrary and makes it hard to see when GC is running since
the GC spans are intermingled with a lot of other trace noise.
The current display is particularly confusing because it creates three
sub-rows in the P row that can overlap each other. Usually a P has
just two sub-rows: one showing the current G and another showing that
G's activity. However, because GC is attributed to a proc, it winds up
as a third row that neither subsumes nor is subsumed by any other row.
This in turn screws up the trace's layout and results in overlapping
events.
Fix these problems by creating a new dedicated row like the existing
"Network" and "Timer" rows and displaying process-wide GC events in
this row. Mark termination and sweep events still appear in their
respective P rows because these are meaningfully attributed.
Change-Id: Ie1a1c6cf8c446e4b043f10f3968f91ff1b546d15
Reviewed-on: https://go-review.googlesource.com/30017
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
cmd/cover, cmd/trace, and cmd/pprof all open browsers.
'go bug' will soon also open a browser.
It is time to unify the browser-handling code.
Change-Id: Iee6b443e21e938aeaaac366a1aefb1afbc7d9b2c
Reviewed-on: https://go-review.googlesource.com/29160
Run-TryBot: Josh Bleecher Snyder <josharian@gmail.com>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Trace viewer cannot handle traces larger than 256MB (limit on js string size):
https://github.com/catapult-project/catapult/issues/627
And even that is problematic (chrome hangs and crashes).
Split large traces into 100MB parts. Somewhat clumsy, but I don't see any other
solution (other than rewriting trace viewer). At least it works reliably now.
Fixes#15482
Change-Id: I993b5f43d22072c6f5bd041ab5888ce176f272b2
Reviewed-on: https://go-review.googlesource.com/22731
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
1.7 traces embed symbol info and we now generate symbolized pprof profiles,
so we don't need the binary. Make binary argument optional as 1.5 traces
still need it.
Change-Id: I65eb13e3d20ec765acf85c42d42a8d7aae09854c
Reviewed-on: https://go-review.googlesource.com/22410
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Austin Clements <austin@google.com>
Generate new protobuf pprof profiles with embed symbol info.
This makes program binary unnecessary.
Change-Id: Ie628439c13c5e34199782031138102c83ea50621
Reviewed-on: https://go-review.googlesource.com/21873
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
This makes traces self-contained and simplifies trace workflow
in modern cloud environments where it is simpler to reach
a service via HTTP than to obtain the binary.
Change-Id: I6ff3ca694dc698270f1e29da37d5efaf4e843a0d
Reviewed-on: https://go-review.googlesource.com/21732
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
This is a subset of https://golang.org/cl/20022 with only the copyright
header lines, so the next CL will be smaller and more reviewable.
Go policy has been single space after periods in comments for some time.
The copyright header template at:
https://golang.org/doc/contribute.html#copyright
also uses a single space.
Make them all consistent.
Change-Id: Icc26c6b8495c3820da6b171ca96a74701b4a01b0
Reviewed-on: https://go-review.googlesource.com/20111
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Reviewed-by: Matthew Dempsky <mdempsky@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
When there is no browser available on the system,
we should print the URL instead of failing.
Change-Id: I4a2b099e17609394273eff150062c285d76bbac1
Reviewed-on: https://go-review.googlesource.com/13774
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
Use runtime.GOROOT instead of os.Getenv("GOROOT") to reference
trace-viewer html file. GOROOT env var is not necessary set,
runtime.GOROOT has a default value for such case.
Change-Id: I906a720f6822915bd9575756e6cbf6d622857c2b
Reviewed-on: https://go-review.googlesource.com/13593
Reviewed-by: Russ Cox <rsc@golang.org>
Move tracing functions from runtime/pprof to the new runtime/trace package.
Fixes#9710
Change-Id: I718bcb2ae3e5959d9f72cab5e6708289e5c8ebd5
Reviewed-on: https://go-review.googlesource.com/12511
Reviewed-by: Russ Cox <rsc@golang.org>
Integrate the latest trace-viewer changes.
It now handles nanoseconds without any issues (thanks to @egonelbre!).
So change timestamps from microseconds to nanoseconds.
Change-Id: I010f27effde7e80c9992e6f276f6912354d27df4
Reviewed-on: https://go-review.googlesource.com/11244
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Reviewed-by: Egon Elbre <egonelbre@gmail.com>
If you have more than 10 procs, then currently they are sorted alphabetically as
0, 10, 11, ..., 19, 2, 20, ...
Assign explicit order to procs so that they are sorted numerically.
Change-Id: I6d978d2cd439aa2fcbcf147842a643f9073eef75
Reviewed-on: https://go-review.googlesource.com/11750
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>
Return a meaningful message when a profile is empty.
Also rename "IO blocking" to "Network blocking",
currently only network blocking is captured.
Fixes#11098
Change-Id: Ib6f1292b8ade4805756fcb6696ba1fca8f9f39a9
Reviewed-on: https://go-review.googlesource.com/11243
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
In generateTrace we check that event timestamp is within the interesting range.
Then later in traceContext.time we double check event time.
However, for some events (e.g. emitSlice) we convert time of ev.Link (slice end) rather than ev itself (slice begin).
Slice end can be outside of the interesting time range, and so traceContext.time crashes.
Remove the check in traceContext.time, check in generateTrace loop is sufficient.
Change-Id: If94e93b5653c5816c0a8dcdd920f15df97616835
Reviewed-on: https://go-review.googlesource.com/11100
Reviewed-by: Andrew Gerrand <adg@golang.org>
