strings.LastIndexByte was introduced in go1.5 and it can be used
effectively wherever the second argument to strings.LastIndex is
exactly one byte long.
This avoids generating unnecessary string symbols and saves
a few calls to strings.LastIndex.
Change-Id: I7b5679d616197b055cffe6882a8675d24a98b574
Reviewed-on: https://go-review.googlesource.com/66372
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
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 extends the GCSweepDone event with counts of swept and reclaimed
bytes. These are useful for understanding the duration and
effectiveness of sweep events.
Change-Id: I3c97a4f0f3aad3adbd188adb264859775f54e2df
Reviewed-on: https://go-review.googlesource.com/40811
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
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>
This adds support to the runtime/trace test for saving traces
collected by its tests to disk and a script in internal/trace that
uses this to collect canned traces for the trace test suite. This can
be used to add to the test suite when we introduce a new trace format
version.
Change-Id: Id9ac1ff312235bf02f982fdfff8a827f54035758
Reviewed-on: https://go-review.googlesource.com/32290
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
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 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>
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>
When tracing is started in the middle of program execution,
we already have a number of runnable goroutines and a number
of blocked/in syscall goroutines. In order to reflect these
goroutines in the trace, we emit EvGoCreate for all existing
goroutines. Then for blocked/in syscall goroutines we additionally
emit EvGoWaiting/EvGoInSyscall events. These events don't reset g.ev
during trace analysis. So next EvGoStart finds g.ev set to the
previous EvGoCreate. As the result time between EvGoCreate and
EvGoStart is accounted as scheduler latency. While in reality
it is blocking/syscall time.
Properly reset g.ev for EvGoWaiting/EvGoInSyscall events.
Change-Id: I0615ba31ed7567600a0667ebb27458481da73adb
Reviewed-on: https://go-review.googlesource.com/25572
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
On some processors cputicks (used to generate trace timestamps)
produce non-monotonic timestamps. It is important that the parser
distinguishes logically inconsistent traces (e.g. missing, excessive
or misordered events) from broken timestamps. The former is a bug
in tracer, the latter is a machine issue.
Test that (1) parser does not return a logical error in case of
broken timestamps and (2) broken timestamps are eventually detected
and reported.
Change-Id: Ib4b1eb43ce128b268e754400ed8b5e8def04bd78
Reviewed-on: https://go-review.googlesource.com/21608
Reviewed-by: Austin Clements <austin@google.com>
Currently tracer uses global sequencer and it introduces
significant slowdown on parallel machines (up to 10x).
Replace the global sequencer with per-goroutine sequencer.
If we assign per-goroutine sequence numbers to only 3 types
of events (start, unblock and syscall exit), it is enough to
restore consistent partial ordering of all events. Even these
events don't need sequence numbers all the time (if goroutine
starts on the same P where it was unblocked, then start does
not need sequence number).
The burden of restoring the order is put on trace parser.
Details of the algorithm are described in the comments.
On http benchmark with GOMAXPROCS=48:
no tracing: 5026 ns/op
tracing: 27803 ns/op (+453%)
with this change: 6369 ns/op (+26%, mostly for traceback)
Also trace size is reduced by ~22%. Average event size before: 4.63
bytes/event, after: 3.62 bytes/event.
Besides running trace tests, I've also tested with manually broken
cputicks (random skew for each event, per-P skew and episodic random skew).
In all cases broken timestamps were detected and no test failures.
Change-Id: I078bde421ccc386a66f6c2051ab207bcd5613efa
Reviewed-on: https://go-review.googlesource.com/21512
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
Reviewed-by: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
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>
Simplify slice/map literal expressions.
Caught with gofmt -d -s, fixed with gofmt -w -s
Checked that the result can still be compiled with Go 1.4.
Change-Id: I06bce110bb5f46ee2f45113681294475aa6968bc
Reviewed-on: https://go-review.googlesource.com/13839
Reviewed-by: Andrew Gerrand <adg@golang.org>
This should fix the solaris/amd64 builder.
Change-Id: Idd6460cc9e842f7b874c9757379986aa723c974c
Reviewed-on: https://go-review.googlesource.com/12922
Reviewed-by: Austin Clements <austin@google.com>
Nearly all the flaky failures we've seen in trace tests have been
due to the use of time stamps to determine relative event ordering.
This is tricky for many reasons, including:
- different cores might not have exactly synchronized clocks
- VMs are worse than real hardware
- non-x86 chips have different timer resolution than x86 chips
- on fast systems two events can end up with the same time stamp
Stop trying to make time reliable. It's clearly not going to be for Go 1.5.
Instead, record an explicit event sequence number for ordering.
Using our own counter solves all of the above problems.
The trace still contains time stamps, of course. The sequence number
is just used for ordering.
Should alleviate #10554 somewhat. Then tickDiv can be chosen to
be a useful time unit instead of having to be exact for ordering.
Separating ordering and time stamps lets the trace parser diagnose
systems where the time stamp order and actual order do not match
for one reason or another. This CL adds that check to the end of
trace.Parse, after all other sequence order-based checking.
If that error is found, we skip the test instead of failing it.
Putting the check in trace.Parse means that cmd/trace will pick
up the same check, refusing to display a trace where the time stamps
do not match actual ordering.
Using net/http's BenchmarkClientServerParallel4 on various CPU counts,
not tracing vs tracing:
name old time/op new time/op delta
ClientServerParallel4 50.4µs ± 4% 80.2µs ± 4% +59.06% (p=0.000 n=10+10)
ClientServerParallel4-2 33.1µs ± 7% 57.8µs ± 5% +74.53% (p=0.000 n=10+10)
ClientServerParallel4-4 18.5µs ± 4% 32.6µs ± 3% +75.77% (p=0.000 n=10+10)
ClientServerParallel4-6 12.9µs ± 5% 24.4µs ± 2% +89.33% (p=0.000 n=10+10)
ClientServerParallel4-8 11.4µs ± 6% 21.0µs ± 3% +83.40% (p=0.000 n=10+10)
ClientServerParallel4-12 14.4µs ± 4% 23.8µs ± 4% +65.67% (p=0.000 n=10+10)
Fixes#10512.
Change-Id: I173eecf8191e86feefd728a5aad25bf1bc094b12
Reviewed-on: https://go-review.googlesource.com/12579
Reviewed-by: Austin Clements <austin@google.com>
As per comments in cl/11834.
Change-Id: I285536b882fa9496e15d77d0d4c16ee913aca581
Reviewed-on: https://go-review.googlesource.com/11861
Reviewed-by: Daniel Theophanes <kardianos@gmail.com>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
On some VMs two events can happen at the same time. For examples:
179827399 GoStart p=2 g=11 off=936359 g=11
179827399 GoUnblock p=2 g=0 off=936355 g=11
If we do non-stable sort, the events can be reordered making the trace inconsistent.
Do stable sort instead.
Batches are dumped in FIFO order, so if these same-time events are split into
separate batches, stable sort still works.
Events on different CPUs go into different batches and can be reordered.
But the intention is that causally-related events on different CPUs
will have larger (non-zero) time diff.
Update #11320
Change-Id: Id1df96af41dff68ea1782ab4b23d5afd63b890c9
Reviewed-on: https://go-review.googlesource.com/11834
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
These were found by grepping the comments from the go code and feeding
the output to aspell.
Change-Id: Id734d6c8d1938ec3c36bd94a4dbbad577e3ad395
Reviewed-on: https://go-review.googlesource.com/10941
Reviewed-by: Aamir Khan <syst3m.w0rm@gmail.com>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Currently, GC disables preemption between the traceGCStart and
traceGCDone, so it never moves Ps. Consequently, the trace verifier
attaches information about GC to its per-P state and will fail if GC
starts on one P and ends on another.
GC will soon be preemptible and may end on a different P than it
began. Hence, this change lifts this per-P verifier state to global
state.
Change-Id: I82256e2baab1ff3c4453fec312079018423b4b51
Reviewed-on: https://go-review.googlesource.com/8714
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
Reviewed-by: Rick Hudson <rlh@golang.org>
Channels and sync.Mutex'es allow another goroutine to acquire resource
ahead of an unblocked goroutine. This is good for performance, but
leads to futile wakeups (the unblocked goroutine needs to block again).
Futile wakeups caused user confusion during the very first evaluation
of tracing functionality on a real server (a goroutine as if acquires a mutex
in a loop, while there is no loop in user code).
This change detects futile wakeups on channels and emits a special event
to denote the fact. Later parser finds entire wakeup sequences
(unblock->start->block) and removes them.
sync.Mutex will be supported in a separate change.
Change-Id: Iaaaee9d5c0921afc62b449a97447445030ac19d3
Reviewed-on: https://go-review.googlesource.com/7380
Reviewed-by: Keith Randall <khr@golang.org>
This allows to test goroutine analysis code in runtime/pprof tests.
Also fix a nil-deref crash in goroutine analysis code that happens on runtime/pprof tests.
Change-Id: Id7884aa29f7fe4a8d7042482a86fe434e030461e
Reviewed-on: https://go-review.googlesource.com/7301
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Keith Randall <khr@golang.org>
Reviewed-by: Andrew Gerrand <adg@golang.org>
Augment ProcStart events with OS thread id.
This helps in scheduler locality analysis.
Change-Id: I93fea75d3072cf68de66110d0b59d07101badcb5
Reviewed-on: https://go-review.googlesource.com/7302
Reviewed-by: Keith Randall <khr@golang.org>
Stip uninteresting bottom and top frames from trace stacks.
This makes both binary and json trace files smaller,
and also makes stacks shorter and more readable in the viewer.
Change-Id: Ib9c80ccc280504f0e235f867f53f1d2652c41583
Reviewed-on: https://go-review.googlesource.com/5523
Reviewed-by: Keith Randall <khr@golang.org>
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
Trace command allows to visualize and analyze traces.
Run as:
$ go tool trace binary trace.file
The commands opens web browser with the main page,
which contains links for trace visualization,
blocking profiler, network IO profiler and per-goroutine
traces.
Also move trace parser from runtime/pprof/trace_parser_test.go
to internal/trace/parser.go, so that it can be shared between
tests and the command.
Change-Id: Ic97ed59ad6e4c7e1dc9eca5e979701a2b4aed7cf
Reviewed-on: https://go-review.googlesource.com/3601
Reviewed-by: Andrew Gerrand <adg@golang.org>
