13 Commits

Author SHA1 Message Date
Russ Cox
ca6f7e45cb runtime/trace: report negative frequency as a time-ordering problem
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>
2015-07-30 20:32:01 +00:00
Russ Cox
80c98fa901 runtime/trace: record event sequence numbers explicitly
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>
2015-07-29 22:32:14 +00:00
Dmitry Vyukov
e1ee31400a internal/trace: fix fuzzer crashers
Fixes #11766
Fixes #11769
Fixes #11767
Fixes #11770

Change-Id: I441382af58f60deb46dcdd70076763b2c47738d4
Reviewed-on: https://go-review.googlesource.com/12378
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
2015-07-18 19:51:50 +00:00
Dmitry Vyukov
1b96091a05 internal/trace: add comment for stable sort
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>
2015-07-02 16:04:07 +00:00
Dmitry Vyukov
64e48bbaba internal/trace: stable sort events
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>
2015-07-02 00:37:16 +00:00
Ainar Garipov
7f9f70e5b6 all: fix misprints in comments
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>
2015-06-11 14:18:57 +00:00
Austin Clements
eec6fdc90b internal/trace: don't assume GC will start and end on same P
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>
2015-04-10 18:21:41 +00:00
Dmitry Vyukov
089d363a91 runtime: fix tracing of syscall exit
Fix tracing of syscall exit after:
https://go-review.googlesource.com/#/c/7504/

Change-Id: Idcde2aa826d2b9a05d0a90a80242b6bfa78846ab
Reviewed-on: https://go-review.googlesource.com/8728
Reviewed-by: Rick Hudson <rlh@golang.org>
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
2015-04-10 17:39:06 +00:00
Dmitry Vyukov
4396ea96c4 runtime: remove futile wakeups from trace
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>
2015-03-17 14:14:55 +00:00
Dmitry Vyukov
7b0c73aa28 cmd/trace: move goroutine analysis code to internal/trace
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>
2015-03-11 12:53:24 +00:00
Dmitry Vyukov
9d332a8324 cmd/trace: dump thread id on proc start
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>
2015-03-11 12:52:41 +00:00
Dmitry Vyukov
919fd24884 runtime: remove runtime frames from stacks in traces
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>
2015-03-10 14:46:15 +00:00
Dmitry Vyukov
edadffa2f3 cmd/trace: add new command
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>
2015-02-20 18:31:25 +00:00