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>
Change-Id: I030baaa0a0abf1e43449faaf676d389a28a868a3
Reviewed-on: https://go-review.googlesource.com/97857
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Peter Weinberger <pjw@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>
CL 92916 added the GOMAXPROCS test in TestTraceSymbolize.
This test only succeeds when the value of GOMAXPROCS changes.
Since the test calls runtime.GOMAXPROCS(1), it will fails
on machines where GOMAXPROCS=1.
This change fixes the test by calling runtime.GOMAXPROCS(oldGoMaxProcs+1).
Fixes#23816.
Change-Id: I1183dbbd7db6077cbd7fa0754032ff32793b2195
Reviewed-on: https://go-review.googlesource.com/93735
Run-TryBot: David du Colombier <0intro@gmail.com>
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
and reorganize test log messages for stack dumps
for easier debugging.
The error log will be formatted like the following:
trace_stack_test.go:282: Did not match event GoCreate with stack
runtime/trace_test.TestTraceSymbolize :39
testing.tRunner :0
Seen 30 events of the type
Offset 1890
runtime/trace_test.TestTraceSymbolize /go/src/runtime/trace/trace_stack_test.go:30
testing.tRunner /go/src/testing/testing.go:777
Offset 1899
runtime/trace_test.TestTraceSymbolize /go/src/runtime/trace/trace_stack_test.go:30
testing.tRunner /go/src/testing/testing.go:777
...
Change-Id: I0468de04507d6ae38ba84d99d13f7bf592e8d115
Reviewed-on: https://go-review.googlesource.com/92916
Reviewed-by: Heschi Kreinick <heschi@google.com>
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
golang.org/cl/81315 attempted to distinguish system goroutines
by examining the function name in the goroutine stack. It assumes that
the information would be available when GoSysBlock or GoInSyscall
events are processed, but it turned out the stack information is
set too late (when the goroutine gets a chance to run).
This change initializes the goroutine information entry when
processing GoCreate event which should be one of the very first
events for the every goroutine in trace.
Fixes#22574
Change-Id: I1ed37087ce2e78ed27c9b419b7d942eb4140cc69
Reviewed-on: https://go-review.googlesource.com/83595
Reviewed-by: Austin Clements <austin@google.com>
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Since Go1.8, different types of GC mark workers were annotated and the
annotation strings were recorded during StartTrace. This change fixes
two issues around the use of traceString from StartTrace here.
1) "failed to parse trace: no consistent ordering of events possible"
This issue is a result of a missing 'batch' event entry. For efficient
tracing, tracer maintains system allocated buffers and once a buffer
is full, it is Flushed out for writing. Moreover, tracing assumes all
the records in the same buffer (batch) are already ordered and implements
more optimization in encoding and defers the completing order
reconstruction till the trace parsing time. Thus, when a Flush happens
and a new buffer is used, the new buffer should contain an event to
indicate the start of a new batch. Before this CL, the batch entry was
written only by traceEvent only when the buffer position is 0 and
wasn't written when flush occurs during traceString.
This CL fixes it by moving the batch entry write to the traceFlush.
2) crash during tracing due to invalid memory access, or during parsing
due to duplicate string entries
This issue is a result of memory allocation during traceString calls.
Execution tracer traces some memory allocation activities. Before this
CL, traceString took the buffer address (*traceBuf) and mutated the buffer.
If memory tracing occurs in the meantime from the same P, the allocation
tracing (traceEvent) will take the same buffer address through the pointer
to the buffer address (**traceBuf), and mutate the buffer.
As a result, one of the followings can happen:
- the allocation record is overwritten by the following trace string
record (data loss)
- if buffer flush occurs during the allocation tracing, traceString
will attempt to write the string record to the old buffer and
eventually causes invalid memory access crash.
- or flush on the same buffer can occur twice (once from the memory
allocation, and once from the string record write), and in this case
the trace can contain the same data twice and the parse will complain
about duplicate string record entries.
This CL fixes the second issue by making the traceString take
**traceBuf (*traceBufPtr).
Change-Id: I24f629758625b38e1916fbfc7d7be6ea210586af
Reviewed-on: https://go-review.googlesource.com/50873
Run-TryBot: Austin Clements <austin@google.com>
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Austin Clements <austin@google.com>
This commit adds an example to the runtime/trace package
on how to use the trace.Start and trace.Stop functions
to trace the execution of a Go program and write
its trace output to a file.
Change-Id: Idf920398f1c3b9d185af9df5ce9293f2361db022
Reviewed-on: https://go-review.googlesource.com/51170
Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com>
This changes the os package to use the runtime poller for file I/O
where possible. When a system call blocks on a pollable descriptor,
the goroutine will be blocked on the poller but the thread will be
released to run other goroutines. When using a non-pollable
descriptor, the os package will continue to use thread-blocking system
calls as before.
For example, on GNU/Linux, the runtime poller uses epoll. epoll does
not support ordinary disk files, so they will continue to use blocking
I/O as before. The poller will be used for pipes.
Since this means that the poller is used for many more programs, this
modifies the runtime to only block waiting for the poller if there is
some goroutine that is waiting on the poller. Otherwise, there is no
point, as the poller will never make any goroutine ready. This
preserves the runtime's current simple deadlock detection.
This seems to crash FreeBSD systems, so it is disabled on FreeBSD.
This is issue 19093.
Using the poller on Windows requires opening the file with
FILE_FLAG_OVERLAPPED. We should only do that if we can remove that
flag if the program calls the Fd method. This is issue 19098.
Update #6817.
Update #7903.
Update #15021.
Update #18507.
Update #19093.
Update #19098.
Change-Id: Ia5197dcefa7c6fbcca97d19a6f8621b2abcbb1fe
Reviewed-on: https://go-review.googlesource.com/36800
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>
This will make it possible to use the poller with the os package.
This is a lot of code movement but the behavior is intended to be
unchanged.
Update #6817.
Update #7903.
Update #15021.
Update #18507.
Change-Id: I1413685928017c32df5654ded73a2643820977ae
Reviewed-on: https://go-review.googlesource.com/36799
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: David Crawshaw <crawshaw@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>
The gcCompat mode was introduced to match the new parser's node position
setup exactly with the positions used by the original parser. Some of the
gcCompat adjustments were required to satisfy syntax error test cases,
and the rest were required to make toolstash cmp pass.
This change removes the former gcCompat adjustments and instead adjusts
the respective test cases as necessary. In some cases this makes the error
lines consistent with the ones reported by gccgo.
Where it has changed, the position associated with a given syntactic construct
is the position (line/col number) of the left-most token belonging to the
construct.
Change-Id: I5b60c00c5999a895c4d6d6e9b383c6405ccf725c
Reviewed-on: https://go-review.googlesource.com/36695
Run-TryBot: Robert Griesemer <gri@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Matthew Dempsky <mdempsky@google.com>
Waiting 2ms for all the kicked-off goroutines to run and block
seems a little optimistic. No harm done by waiting for 200ms instead.
Fixes#17238.
Change-Id: I827532ea2f5f1f3ed04179f8957dd2c563946ed0
Reviewed-on: https://go-review.googlesource.com/32103
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
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>
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>
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 change consolidates functions and methods related to TCPAddr,
TCPConn and TCPListener for maintenance purpose, especially for
documentation. Also refactors Dial error code paths.
The followup changes will update comments and examples.
Updates #10624.
Change-Id: I3333ee218ebcd08928f9e2826cd1984d15ea153e
Reviewed-on: https://go-review.googlesource.com/20009
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Run-TryBot: Mikio Hara <mikioh.mikioh@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
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>
Reduce allocation to avoid running out of memory on the openbsd/arm builder,
until issue/12032 is resolved.
Update issue #12032
Change-Id: Ibd513829ffdbd0db6cd86a0a5409934336131156
Reviewed-on: https://go-review.googlesource.com/15242
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
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>
For the android/arm builder.
Change-Id: Iad4881689223cd6479870da9541524a8cc458cce
Reviewed-on: https://go-review.googlesource.com/12859
Reviewed-by: Andrew Gerrand <adg@golang.org>
Run-TryBot: David Crawshaw <crawshaw@golang.org>
The skips added in CL 12579, based on incorrect time stamps,
should be sufficient to identify and exclude all the time-related
flakiness on these systems.
If there is other flakiness, we want to find out.
For #10512.
Change-Id: I5b588ac1585b2e9d1d18143520d2d51686b563e3
Reviewed-on: https://go-review.googlesource.com/12746
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>
We use 127.0.0.1 instead of localhost in Go networking tests.
The reporter of #11774 has localhost defined to be 120.192.83.162,
for reasons unknown.
Also, if TestTraceSymbolize calls Fatalf (for example because Listen
fails) then we need to stop the trace for future tests to work.
See failure log in #11774.
Fixes#11774.
Change-Id: Iceddb03a72d31e967acd2d559ecb78051f9c14b7
Reviewed-on: https://go-review.googlesource.com/12521
Reviewed-by: Rob Pike <r@golang.org>
Move tracing functions from runtime/pprof to the new runtime/trace package.
Fixes#9710
Change-Id: I718bcb2ae3e5959d9f72cab5e6708289e5c8ebd5
Reviewed-on: https://go-review.googlesource.com/12511
Reviewed-by: Russ Cox <rsc@golang.org>
Hana Kim
Kunpei Sakai
David du Colombier
Hana (Hyang-Ah) Kim
André Carvalho
David Lazar
Ian Lance Taylor
Robert Griesemer
Russ Cox
Austin Clements
Dmitry Vyukov
Mikio Hara
Brad Fitzpatrick
Joel Sing
Didier Spezia
David Crawshaw