| Age | Commit message (Collapse) | Author |
|---|
|
parser.go is an old file that contains trace v1 definitions and a second
equivalent definition for stack frames. These are redundant and useless.
Delete these definitions and rename the file to fakep.go, which
describes the only thing left in this file, a bunch of fake P IDs used
by the trace viewer.
We should consider moving the fake P definitions elsewhere, too.
Change-Id: Ifd0768bd73c39009069445afe0155f1e352f00c3
Reviewed-on: https://go-review.googlesource.com/c/go/+/644875
Reviewed-by: Michael Pratt <mpratt@google.com>
Auto-Submit: Michael Knyszek <mknyszek@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
|
|
This change removes unused parts of the v1 tracer in preperation of
the move of the v2 tracer into the trace package.
Updates #67367
Change-Id: I3e53a8afdef72dc90c2d5b514380d1077d284bc7
Reviewed-on: https://go-review.googlesource.com/c/go/+/584537
Reviewed-by: Michael Knyszek <mknyszek@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
|
|
This change refactors the cmd/trace package and adds most of the support
for v2 traces.
The following features of note are missing in this CL and will be
implemented in follow-up CLs:
- The focustask filter for the trace viewer
- The taskid filter for the trace viewer
- The goid filter for the trace viewer
- Pprof profiles
- The MMU graph
- The goroutine analysis pages
- The task analysis pages
- The region analysis pages
This CL makes one notable change to the trace CLI: it makes the -d flag
accept an integer to set the debug mode. For old traces -d != 0 works
just like -d. For new traces -d=1 means the high-level events and -d=2
means the low-level events.
Thanks to Felix Geisendörfer (felix.geisendoerfer@datadoghq.com) for
doing a lot of work on this CL; I picked this up from him and got a
massive headstart as a result.
For #60773.
For #63960.
Change-Id: I3626e22473227c5980134a85f1bb6a845f567b1b
Reviewed-on: https://go-review.googlesource.com/c/go/+/542218
Reviewed-by: Michael Pratt <mpratt@google.com>
Auto-Submit: Michael Knyszek <mknyszek@google.com>
TryBot-Bypass: Michael Knyszek <mknyszek@google.com>
|
|
Currently STW events are only emitted for GC STWs. There's little reason
why the trace can't contain events for every STW: they're rare so don't
take up much space in the trace, yet being able to see when the world
was stopped is often critical to debugging certain latency issues,
especially when they stem from user-level APIs.
This change adds new "kinds" to the EvGCSTWStart event, renames the
GCSTW events to just "STW," and lets the parser deal with unknown STW
kinds for future backwards compatibility.
But, this change must break trace compatibility, so it bumps the trace
version to Go 1.21.
This change also includes a small cleanup in the trace command, which
previously checked for STW events when deciding whether user tasks
overlapped with a GC. Looking at the source, I don't see a way for STW
events to ever enter the stream that that code looks at, so that
condition has been deleted.
Change-Id: I9a5dc144092c53e92eb6950e9a5504a790ac00cf
Reviewed-on: https://go-review.googlesource.com/c/go/+/494495
Reviewed-by: Michael Pratt <mpratt@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Michael Knyszek <mknyszek@google.com>
|
|
A previous iteration of the tracer's user annotation API had different
names for tasks and regions, and used to return functions for ending
them rather than types with End methods. This CL updates the doc
comments to reflect those changes, and also fixes up the internal
documentation of the events (similar to go.dev/cl/465335, the stack
argument was in the wrong place in the list).
The User Log event internal documentation might also look wrong since
the value argument follows the stack argument. However, the User Log
event is a special case where the log message is appended immediately
following the normal event, including the stack argument. There isn't
much room to clarify this next to the event type definitions, so this CL
clarifies the comment where the event is encoded.
Change-Id: I846c709f6026ef01c0a272557d6390b2c17074e0
Reviewed-on: https://go-review.googlesource.com/c/go/+/472955
Reviewed-by: Michael Pratt <mpratt@google.com>
Reviewed-by: Carlos Amedee <carlos@golang.org>
Auto-Submit: Michael Pratt <mpratt@google.com>
Run-TryBot: Michael Pratt <mpratt@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Nick Ripley <nick.ripley@datadoghq.com>
|
|
Fixes #58327
Change-Id: I15593e6ee42e04f2de13804ef26e0e66a2307db0
GitHub-Last-Rev: 7e0d04b503d2ba217b76b1ac668a67cd72ec6d7c
GitHub-Pull-Request: golang/go#58338
Reviewed-on: https://go-review.googlesource.com/c/go/+/465335
Reviewed-by: Michael Knyszek <mknyszek@google.com>
Run-TryBot: Michael Knyszek <mknyszek@google.com>
Auto-Submit: Michael Knyszek <mknyszek@google.com>
Reviewed-by: David Chase <drchase@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
|
|
Change-Id: Ic7f827b8ee758c991ed76be65026b0330207deea
Reviewed-on: https://go-review.googlesource.com/c/go/+/428262
Reviewed-by: Ian Lance Taylor <iant@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Ian Lance Taylor <iant@google.com>
Auto-Submit: Ian Lance Taylor <iant@google.com>
Reviewed-by: Michael Pratt <mpratt@google.com>
|
|
Update instructions to match what seems to be the historical practice:
to generate canned traces when a version is finalized, rather than
waiting until it is superseded.
Follow rename of trace-internal tests from "Span" to "Region". Update
the net/http test invocation to match the apparent intent and the actual
http_1_5_good behavior (about 7ms of total run time and trace file size
under 50kB).
Change-Id: Ifd4c85882159478852e0b8f0d771b6f16b8f3c1b
Reviewed-on: https://go-review.googlesource.com/c/go/+/413776
Run-TryBot: Rhys Hiltner <rhys@justin.tv>
Reviewed-by: Carlos Amedee <carlos@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Michael Pratt <mpratt@google.com>
|
|
When the CPU profiler and execution tracer are both active, report the
CPU profile samples in the execution trace data stream.
Include only samples that arrive on the threads known to the runtime,
but include them even when running g0 (such as near the scheduler) or if
there's no P (such as near syscalls).
Render them in "go tool trace" as instantaneous events.
For #16895
Change-Id: I0aa501a7b450c971e510961c0290838729033f7f
Reviewed-on: https://go-review.googlesource.com/c/go/+/400795
Reviewed-by: Michael Knyszek <mknyszek@google.com>
Run-TryBot: Rhys Hiltner <rhys@justin.tv>
Reviewed-by: David Chase <drchase@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
|
|
This change moves next_gc and last_next_gc into gcControllerState under
the names heapGoal and lastHeapGoal respectively. These are
fundamentally GC pacer related values, and so it makes sense for them to
live here.
Partially generated by
rf '
ex . {
memstats.next_gc -> gcController.heapGoal
memstats.last_next_gc -> gcController.lastHeapGoal
}
'
except for updates to comments and gcControllerState methods, where
they're accessed through the receiver, and trace-related renames of
NextGC -> HeapGoal, while we're here.
For #44167.
Change-Id: I1e871ad78a57b01be8d9f71bd662530c84853bed
Reviewed-on: https://go-review.googlesource.com/c/go/+/306603
Trust: Michael Knyszek <mknyszek@google.com>
Run-TryBot: Michael Knyszek <mknyszek@google.com>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Michael Pratt <mpratt@google.com>
|
|
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
|
|
As found by unparam. Picked the low-hanging fruit, consisting only of
errors that were always nil and results that were never used. Left out
those that were useful for consistency with other func signatures.
Change-Id: I06b52bbd3541f8a5d66659c909bd93cb3e172018
Reviewed-on: https://go-review.googlesource.com/102418
Run-TryBot: Daniel Martí <mvdan@mvdan.cc>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
|
|
This is an updated version of golang.org/cl/96395, with the fix to
TestUserSpan.
This reverts commit 7b6f6267e90a8e4eab37a3f2164ba882e6222adb.
Change-Id: I31eec8ba0997f9178dffef8dac608e731ab70872
Reviewed-on: https://go-review.googlesource.com/98236
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Heschi Kreinick <heschi@google.com>
|
|
This reverts commit 16398894dccf06e34af8fb1c7cff6eed9b163057.
This broke TestUserTaskSpan test.
Change-Id: If5ff8bdfe84e8cb30787b03ead87205ece3d5601
Reviewed-on: https://go-review.googlesource.com/98235
Reviewed-by: Heschi Kreinick <heschi@google.com>
|
|
Even though undocumented, the assumption is the Event's link field
points to the following event in the future. The new span/task event
processing breaks the assumption.
Change-Id: I4ce2f30c67c4f525ec0a121a7e43d8bdd2ec3f77
Reviewed-on: https://go-review.googlesource.com/96395
Reviewed-by: Heschi Kreinick <heschi@google.com>
|
|
Also add testdata for version 1.11 including UserTaskSpan test trace.
Change-Id: I673fb29bb3aee96a14fadc0ab860d4f5832143f5
Reviewed-on: https://go-review.googlesource.com/93795
Reviewed-by: Heschi Kreinick <heschi@google.com>
|
|
This implements the annotation API proposed in golang.org/cl/63274.
traceString is updated to protect the string map with trace.stringsLock
because the assumption that traceString is called by a single goroutine
(either at the beginning of tracing and at the end of tracing when
dumping all the symbols and function names) is no longer true.
traceString is used by the annotation apis (NewContext, StartSpan, Log)
to register frequently appearing strings (task and span names, and log
keys) after this change.
NewContext -> one or two records (EvString, EvUserTaskCreate)
end function -> one record (EvUserTaskEnd)
StartSpan -> one or two records (EvString, EvUserSpan)
span end function -> one or two records (EvString, EvUserSpan)
Log -> one or two records (EvString, EvUserLog)
EvUserLog record is of the typical record format written by traceEvent
except that it is followed by bytes that represents the value string.
In addition to runtime/trace change, this change includes
corresponding changes in internal/trace to parse the new record types.
Future work to improve efficiency:
More efficient unique task id generation instead of atomic. (per-P
counter).
Instead of a centralized trace.stringsLock, consider using per-P
string cache or something more efficient.
R=go1.11
Change-Id: Iec9276c6c51e5be441ccd52dec270f1e3b153970
Reviewed-on: https://go-review.googlesource.com/71690
Reviewed-by: Austin Clements <austin@google.com>
|
|
This CL presents the proposed user annotation API skeleton.
This CL bumps up the trace version to 1.11.
Design doc https://goo.gl/iqJfJ3
Implementation CLs are followed.
The API introduces three basic building blocks. Log, Span, and Task.
Log is for basic logging. When called, the message will be recorded
to the trace along with timestamp, goroutine id, and stack info.
trace.Log(ctx, messageType message)
Span can be thought as an extension of log to record interesting
time interval during a goroutine's execution. A span is local to a
goroutine by definition.
trace.WithSpan(ctx, "doVeryExpensiveOp", func(ctx context) {
/* do something very expensive */
})
Task is higher-level concept that aids tracing of complex operations
that encompass multiple goroutines or are asynchronous.
For example, an RPC request, a HTTP request, a file write, or a
batch job can be traced with a Task.
Note we chose to design the API around context.Context so it allows
easier integration with other tracing tools, often designed around
context.Context as well. Log and WithSpan APIs recognize the task
information embedded in the context and record it in the trace as
well. That allows the Go execution tracer to associate and group
the spans and log messages based on the task information.
In order to create a Task,
ctx, end := trace.NewContext(ctx, "myTask")
defer end()
The Go execution tracer measures the time between the task created
and the task ended for the task latency.
More discussion history in golang.org/cl/59572.
Update #16619
R=go1.11
Change-Id: I59a937048294dafd23a75cf1723c6db461b193cd
Reviewed-on: https://go-review.googlesource.com/63274
Reviewed-by: Austin Clements <austin@google.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>
|
|
This reverts https://golang.org/cl/66372.
Updates #22148
Change-Id: I3e94af3dfc11a2883bf28e1d5e1f32f98760b3ee
Reviewed-on: https://go-review.googlesource.com/68431
Reviewed-by: Ian Lance Taylor <iant@golang.org>
|
|
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>
|
|
Use per-P timers, so each P may work with its own timers.
This CL improves performance on multi-CPU systems
in the following cases:
- When serving high number of concurrent connections
with read/write deadlines set (for instance, highly loaded
net/http server).
- When using high number of concurrent timers. These timers
may be implicitly created via context.WithDeadline
or context.WithTimeout.
Production servers should usually set timeout on connections
and external requests in order to prevent from resource leakage.
See https://blog.cloudflare.com/the-complete-guide-to-golang-net-http-timeouts/
Below are relevant benchmark results for various GOMAXPROCS values
on linux/amd64:
context package:
name old time/op new time/op delta
WithTimeout/concurrency=40 4.92µs ± 0% 5.17µs ± 1% +5.07% (p=0.000 n=9+9)
WithTimeout/concurrency=4000 6.03µs ± 1% 6.49µs ± 0% +7.63% (p=0.000 n=8+10)
WithTimeout/concurrency=400000 8.58µs ± 7% 9.02µs ± 4% +5.02% (p=0.019 n=10+10)
name old time/op new time/op delta
WithTimeout/concurrency=40-2 3.70µs ± 1% 2.78µs ± 4% -24.90% (p=0.000 n=8+9)
WithTimeout/concurrency=4000-2 4.49µs ± 4% 3.67µs ± 5% -18.26% (p=0.000 n=10+10)
WithTimeout/concurrency=400000-2 6.16µs ±10% 5.15µs ±13% -16.30% (p=0.000 n=10+10)
name old time/op new time/op delta
WithTimeout/concurrency=40-4 3.58µs ± 1% 2.64µs ± 2% -26.13% (p=0.000 n=9+10)
WithTimeout/concurrency=4000-4 4.17µs ± 0% 3.32µs ± 1% -20.36% (p=0.000 n=10+10)
WithTimeout/concurrency=400000-4 5.57µs ± 9% 4.83µs ±10% -13.27% (p=0.001 n=10+10)
time package:
name old time/op new time/op delta
AfterFunc 6.15ms ± 3% 6.07ms ± 2% ~ (p=0.133 n=10+9)
AfterFunc-2 3.43ms ± 1% 3.56ms ± 1% +3.91% (p=0.000 n=10+9)
AfterFunc-4 5.04ms ± 2% 2.36ms ± 0% -53.20% (p=0.000 n=10+9)
After 6.54ms ± 2% 6.49ms ± 3% ~ (p=0.393 n=10+10)
After-2 3.68ms ± 1% 3.87ms ± 0% +5.14% (p=0.000 n=9+9)
After-4 6.66ms ± 1% 2.87ms ± 1% -56.89% (p=0.000 n=10+10)
Stop 698µs ± 2% 689µs ± 1% -1.26% (p=0.011 n=10+10)
Stop-2 729µs ± 2% 434µs ± 3% -40.49% (p=0.000 n=10+10)
Stop-4 837µs ± 3% 333µs ± 2% -60.20% (p=0.000 n=10+10)
SimultaneousAfterFunc 694µs ± 1% 692µs ± 7% ~ (p=0.481 n=10+10)
SimultaneousAfterFunc-2 714µs ± 3% 569µs ± 2% -20.33% (p=0.000 n=10+10)
SimultaneousAfterFunc-4 782µs ± 2% 386µs ± 2% -50.67% (p=0.000 n=10+10)
StartStop 267µs ± 3% 274µs ± 0% +2.64% (p=0.000 n=8+9)
StartStop-2 238µs ± 2% 140µs ± 3% -40.95% (p=0.000 n=10+8)
StartStop-4 320µs ± 1% 125µs ± 1% -61.02% (p=0.000 n=9+9)
Reset 75.0µs ± 1% 77.5µs ± 2% +3.38% (p=0.000 n=10+10)
Reset-2 150µs ± 2% 40µs ± 5% -73.09% (p=0.000 n=10+9)
Reset-4 226µs ± 1% 33µs ± 1% -85.42% (p=0.000 n=10+10)
Sleep 857µs ± 6% 878µs ± 9% ~ (p=0.079 n=10+9)
Sleep-2 617µs ± 4% 585µs ± 2% -5.21% (p=0.000 n=10+10)
Sleep-4 689µs ± 3% 465µs ± 4% -32.53% (p=0.000 n=10+10)
Ticker 55.9ms ± 2% 55.9ms ± 2% ~ (p=0.971 n=10+10)
Ticker-2 28.7ms ± 2% 28.1ms ± 1% -2.06% (p=0.000 n=10+10)
Ticker-4 14.6ms ± 0% 13.6ms ± 1% -6.80% (p=0.000 n=9+10)
Fixes #15133
Change-Id: I6f4b09d2db8c5bec93146db6501b44dbfe5c0ac4
Reviewed-on: https://go-review.googlesource.com/34784
Reviewed-by: Austin Clements <austin@google.com>
|
|
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>
|
|
Change-Id: Id25c90993c4cbb7449d7031301b6d214a67d7633
Reviewed-on: https://go-review.googlesource.com/24134
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
|
|
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>
|
|
Change-Id: I037101b1921fe151695d32e9874b50dd64982298
Reviewed-on: https://go-review.googlesource.com/22314
Reviewed-by: Austin Clements <austin@google.com>
|
|
Fixes #15102
Change-Id: I7fdb6464afd0b7af9b6652051416f0fddd34dc9a
Reviewed-on: https://go-review.googlesource.com/21730
Reviewed-by: Austin Clements <austin@google.com>
|
|
1. Parse out version from trace header.
2. Restore handling of 1.5 traces.
3. Restore optional symbolization of traces.
4. Add some canned 1.5 traces for regression testing
(http benchmark trace, runtime/trace stress traces,
plus one with broken timestamps).
Change-Id: Idb18a001d03ded8e13c2730eeeb37c5836e31256
Reviewed-on: https://go-review.googlesource.com/21803
Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Austin Clements <austin@google.com>
|
|
Change-Id: Id79eaa6d49dae80c334c7243b0a5bbcdcb9397d3
Reviewed-on: https://go-review.googlesource.com/21758
Reviewed-by: Mikio Hara <mikioh.mikioh@gmail.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>
|
|
Change-Id: Iba82a5bd3846f7ab038cc10ec72ff6bcd2c0b484
Reviewed-on: https://go-review.googlesource.com/21377
Run-TryBot: Dave Cheney <dave@cheney.net>
Reviewed-by: Dave Cheney <dave@cheney.net>
|
|
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>
|
|
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>
|
|
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>
|
