Extra Ms may lead to the "no consistent ordering of events possible" error when parsing trace file with cgo enabled, since:
1. The gs in the extra Ms may be in `_Gdead` status while starting trace by invoking `runtime.StartTrace`,
2. and these gs will trigger `traceEvGoSysExit` events in `runtime.exitsyscall` when invoking go functions from c,
3. then, the events of those gs are under non-consistent ordering, due to missing the previous events.
Add two events, `traceEvGoCreate` and `traceEvGoInSyscall`, in `runtime.StartTrace`, will make the trace parser happy.
Fixes#29707
Change-Id: I2fd9d1713cda22f0ddb36efe1ab351f88da10881
GitHub-Last-Rev: 7bbfddb81b
GitHub-Pull-Request: golang/go#54974
Reviewed-on: https://go-review.googlesource.com/c/go/+/429858
Run-TryBot: Michael Pratt <mpratt@google.com>
Reviewed-by: Michael Pratt <mpratt@google.com>
Reviewed-by: Bryan Mills <bcmills@google.com>
Run-TryBot: xie cui <523516579@qq.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Auto-Submit: Michael Pratt <mpratt@google.com>
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>
Extra Ms may lead to the "no consistent ordering of events possible" error when parsing trace file with cgo enabled, since:
1. The gs in the extra Ms may be in `_Gdead` status while starting trace by invoking `runtime.StartTrace`,
2. and these gs will trigger `traceEvGoSysExit` events in `runtime.exitsyscall` when invoking go functions from c,
3. then, the events of those gs are under non-consistent ordering, due to missing the previous events.
Add two events, `traceEvGoCreate` and `traceEvGoInSyscall`, in `runtime.StartTrace`, will make the trace parser happy.
Fixes#29707
Change-Id: I7cc4b80822d2c46591304a59c9da2c9fc470f1d0
GitHub-Last-Rev: 445de8eaf3
GitHub-Pull-Request: golang/go#53284
Reviewed-on: https://go-review.googlesource.com/c/go/+/411034
Run-TryBot: Michael Pratt <mpratt@google.com>
Reviewed-by: Michael Knyszek <mknyszek@google.com>
Auto-Submit: Michael Pratt <mpratt@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Michael Pratt <mpratt@google.com>
If a goroutine is started within a user region, internal/trace assigns
the child goroutine a nameless region for its entire lifetime which is
assosciated the same task as the parent's region.
This is not strictly necessary: a child goroutine is not necessarily
related to the task unless it performs some task operation (in which
case it will be associated with the task through the standard means).
However, it can be quite handy to see child goroutines within a region,
which may be child worker goroutines that you simply didn't perform task
operations on.
If the first GC occurs during a region, the GC worker goroutines will
also inherit a child region. We know for sure that these aren't related
to the task, so filter them out from the region list.
Note that we can't exclude system goroutines from setting activeRegions
in EvGoCreate handling, because we don't know the goroutine start
function name until the first EvGoStart.
Fixes#53784.
Change-Id: Ic83d84e23858a8400a76d1ae2f1418ef49951178
Reviewed-on: https://go-review.googlesource.com/c/go/+/416858
Run-TryBot: Michael Pratt <mpratt@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Michael Knyszek <mknyszek@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>
And then revert the bootstrap cmd directories and certain testdata.
And adjust tests as needed.
Not reverting the changes in std that are bootstrapped,
because some of those changes would appear in API docs,
and we want to use any consistently.
Instead, rewrite 'any' to 'interface{}' in cmd/dist for those directories
when preparing the bootstrap copy.
A few files changed as a result of running gofmt -w
not because of interface{} -> any but because they
hadn't been updated for the new //go:build lines.
Fixes#49884.
Change-Id: Ie8045cba995f65bd79c694ec77a1b3d1fe01bb09
Reviewed-on: https://go-review.googlesource.com/c/go/+/368254
Trust: Russ Cox <rsc@golang.org>
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Robert Griesemer <gri@golang.org>
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>
os.ReadDir is a replacement for ioutil.ReadDir that returns
a slice of fs.DirEntry instead of fs.FileInfo, meaning it is the
more efficient form.
This CL updates call sites throughout the Go source tree
wherever possible. As usual, code built using the Go 1.4
bootstrap toolchain is not included. There is also a use in
go/build that appears in the public API and can't be changed,
at least not without additional changes.
Fixes#42026.
Change-Id: Icfc9dd52c6045020f6830e22c72128499462d561
Reviewed-on: https://go-review.googlesource.com/c/go/+/266366
Trust: Russ Cox <rsc@golang.org>
Run-TryBot: Russ Cox <rsc@golang.org>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
As part of #42026, these helpers from io/ioutil were moved to os.
(ioutil.TempFile and TempDir became os.CreateTemp and MkdirTemp.)
Update the Go tree to use the preferred names.
As usual, code compiled with the Go 1.4 bootstrap toolchain
and code vendored from other sources is excluded.
ReadDir changes are in a separate CL, because they are not a
simple search and replace.
For #42026.
Change-Id: If318df0216d57e95ea0c4093b89f65e5b0ababb3
Reviewed-on: https://go-review.googlesource.com/c/go/+/266365
Trust: Russ Cox <rsc@golang.org>
Run-TryBot: Russ Cox <rsc@golang.org>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Shorten some of the longest tests that run during all.bash.
Removes 7r 50u 21s from all.bash.
After this change, all.bash is under 5 minutes again on my laptop.
For #26473.
Change-Id: Ie0460aa935808d65460408feaed210fbaa1d5d79
Reviewed-on: https://go-review.googlesource.com/c/go/+/177559
Run-TryBot: Russ Cox <rsc@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
The performance improvement is not as big as we hoped.
Until the API is feature complete, we postpone the release
and avoid added complexity.
This change was prepared by reverting all the changes affected
src/cmd/trace and src/internal/traceparser packages after
golang.org/cl/137635, and then bringing back MMU computation
APIs (originally in src/internal/traceparser) to the
src/internal/trace package.
Revert "cmd/trace: use new traceparser to parse the raw trace files"
This reverts https://golang.org/cl/145457
(commit 08816cb8d7).
Revert "internal/traceparser: provide parser that uses less space and parses segments of runtime trace files"
This reverts https://golang.org/cl/137635
(commit daaf361f74).
Change-Id: Ic2a068a7dbaf4053cd9674ca7bde9c58e74385b4
Reviewed-on: https://go-review.googlesource.com/c/150517
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Austin Clements <austin@google.com>
This reverts commit 1764609b8b.
Reason for revert: It breaks the dragonfly trybot, in which there are sometimes (non-deterministically) Events with the same timestamp that have to occur in a specific order.
Change-Id: I714e640c6ab5ccb23d5577e8aa98c7716ede7ad2
Reviewed-on: https://go-review.googlesource.com/114356
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
The existing code just used timestamps. The new code uses more fields
when timestamps are equal.
Revised to shorten code per reviewer comments.
Change-Id: Ibd0824d0acd7644484d536b1a754a0da156fac3d
Reviewed-on: https://go-review.googlesource.com/113721
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.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>
When snapshotting the execution time stats of a goroutine
we take into account the intermediate values kepts in the GDesc's
gdesc field. At the end of goroutine analysis, we go through all
goroutines and replace the GExecutionStat with the new snapshot.
Here the mistake was that we replaced the GExecutionStat with
the value that reflects the intermediate values, but did clear
the intermediate values. So, when the following finalizeActiveSpans
runs, it trieds to add the intermediate values again (double-counting)
when taking a snapshot.
Fix the issue by using the finalized GExecutionStat instead of
recomputing the snapshot. While we are here, refactor the finalization
logic so it can be used when processing GoEnd, GoStop events.
Change-Id: Ibdb342214c29b65d4ea37e52b1f8b83f1fb20143
Reviewed-on: https://go-review.googlesource.com/103157
Reviewed-by: Peter Weinberger <pjw@google.com>
Move part of UserSpan event processing from cmd/trace.analyzeAnnotations
to internal/trace.GoroutineStats that returns analyzed per-goroutine
execution information. Now the execution information includes list of
spans and their execution information.
cmd/trace.analyzeAnnotations utilizes the span execution information
from internal/trace.GoroutineStats and connects them with task
information.
Change-Id: Ib7f79a3ba652a4ae55cd81ea17565bcc7e241c5c
Reviewed-on: https://go-review.googlesource.com/101917
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Heschi Kreinick <heschi@google.com>
Reviewed-by: Peter Weinberger <pjw@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>
Goroutine analysis reports the sum of all overlapping GC intervals as
the GCTime of a goroutine. The computation is done by adding the length
of a completed GC interval to 'active' goroutines when processing the
corresponding EvGCDone event. This change fixes the two corner cases
the current implementation ignores:
1) Goroutine that ends during GC. Previously, this goroutine was ignored
and GC time was undercounted. We handle this case by setting the
gcStartTime only when GC is active and handling non-zero gcStartTime
when processing EvGoStop and EvGoStart.
2) Goroutine that starts during GC. Previously, the entire GC interval
length was added to the Goroutine's GCTime which resulted in overcount
of GC time. We handle this case by computing the length of overlapped
period precisely.
Change-Id: Ifa8e82672ec341b5ff87837209f4311fa7262b7f
Reviewed-on: https://go-review.googlesource.com/100842
Reviewed-by: Heschi Kreinick <heschi@google.com>
Run-TryBot: Heschi Kreinick <heschi@google.com>
TryBot-Result: Gobot Gobot <gobot@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>
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>
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>
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>
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>
