summaryrefslogtreecommitdiff
path: root/src/internal/trace
Commit message (Collapse)AuthorAgeFilesLines
* internal/trace: don't report regions on system goroutinesMichael Pratt2022-07-111-9/+28
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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>
* internal/trace: add Go 1.19 test dataRhys Hiltner2022-06-247-5/+5
| | | | | | | | | | | | | | | | | | 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>
* runtime: add CPU samples to execution traceRhys Hiltner2022-05-032-3/+31
| | | | | | | | | | | | | | | | | | | | 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>
* all: gofmt -w -r 'interface{} -> any' srcRuss Cox2021-12-131-4/+4
| | | | | | | | | | | | | | | | | | | | | | | | 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>
* runtime: move next_gc and last_next_gc into gcControllerStateMichael Anthony Knyszek2021-04-141-3/+3
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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>
* all: update to use os.ReadDir where appropriateRuss Cox2020-12-091-4/+3
| | | | | | | | | | | | | | | | | | | | | 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>
* all: update to use os.ReadFile, os.WriteFile, os.CreateTemp, os.MkdirTempRuss Cox2020-12-092-4/+4
| | | | | | | | | | | | | | | | | | | | | | 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>
* internal/trace: add license header to writer.goPovilas Versockas2020-05-101-0/+4
| | | | | | Change-Id: I9f23490a565b81b155642fe301f897c1d0af03fd Reviewed-on: https://go-review.googlesource.com/c/go/+/232810 Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com>
* all: shorten some testsRuss Cox2019-05-222-2/+15
| | | | | | | | | | | | | | | 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>
* cmd/trace: revert internal/traceparserHana Kim2018-11-224-0/+1333
| | | | | | | | | | | | | | | | | | | | | | | | | | 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 08816cb8d7ed16b9c804587ff02c1ad1c3af6cd5). Revert "internal/traceparser: provide parser that uses less space and parses segments of runtime trace files" This reverts https://golang.org/cl/137635 (commit daaf361f74c3665bcb364356c5a9dd9f536c78c3). 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>
* all: fix typos detected by github.com/client9/misspellKazuhiro Sera2018-08-231-1/+1
| | | | | | | | | | Change-Id: Iadb3c5de8ae9ea45855013997ed70f7929a88661 GitHub-Last-Rev: ae85bcf82be8fee533e2b9901c6133921382c70a GitHub-Pull-Request: golang/go#26920 Reviewed-on: https://go-review.googlesource.com/128955 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org> Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org>
* Revert "internal/trace: change Less to make sorting events deterministice"Peter Weinberger2018-05-241-15/+2
| | | | | | | | | | This reverts commit 1764609b8b245323210eab39c4b586291d3a45a5. 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>
* internal/trace: change Less to make sorting events deterministicePeter Weinberger2018-05-231-2/+15
| | | | | | | | | | | 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>
* runtime/trace: rename "Span" with "Region"Hana Kim2018-04-242-60/+60
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | "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>
* internal/trace: fix double counting in span analysisHana Kim2018-03-281-23/+24
| | | | | | | | | | | | | | | | | | | | 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>
* internal/trace: compute span stats as computing goroutine statsHana Kim2018-03-261-25/+163
| | | | | | | | | | | | | | | | | | 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>
* all: remove some unused return parametersDaniel Martí2018-03-241-6/+3
| | | | | | | | | | | | 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>
* internal/trace: fix GC time computation of short goroutinesHana Kim2018-03-151-2/+17
| | | | | | | | | | | | | | | | | | | | | | | | 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>
* internal/trace: remove backlinks from span/task end to startHana Kim2018-03-051-6/+5
| | | | | | | | | | | | | 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>
* internal/trace: Revert "remove backlinks from span/task end to start"Hana Kim2018-03-021-5/+6
| | | | | | | | | 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>
* internal/trace: remove backlinks from span/task end to startHana Kim2018-03-021-6/+5
| | | | | | | | | | 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>
* internal/trace: link user span start and end eventsHana Kim2018-02-156-2/+42
| | | | | | | | 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>
* runtime/trace: implement annotation APIHana Kim2018-02-151-55/+108
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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>
* runtime/trace: user annotation APIHana Kim2018-02-151-2/+10
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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>
* cmd/trace: init goroutine info entries with GoCreate eventHana Kim2017-12-202-14/+22
| | | | | | | | | | | | | | | | | | | | 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>
* all: revert "all: prefer strings.LastIndexByte over strings.LastIndex"Marvin Stenger2017-10-051-1/+1
| | | | | | | | | | 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>
* all: prefer strings.LastIndexByte over strings.LastIndexMarvin Stenger2017-09-271-1/+1
| | | | | | | | | | | | | | | 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>
* all: correct location of go toolHiroshi Ioka2017-09-201-1/+15
| | | | | | | | | | | | | | | | | | | | | 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>
* runtime: improve timers scalability on multi-CPU systemsAliaksandr Valialkin2017-09-121-3/+4
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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>
* runtime,cmd/trace: trace GC STW eventsAustin Clements2017-08-294-20/+45
| | | | | | | | | | | | | | | | | | | | | | 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>
* runtime: record swept and reclaimed bytes in sweep traceAustin Clements2017-04-194-8/+13
| | | | | | | | | | | | 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>
* cmd/trace: Record mark assists in execution tracesHeschi Kreinick2017-02-105-94/+112
| | | | | | | | | | | | | | | | | | | | 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>
* runtime/trace, internal/trace: script to collect canned tracesAustin Clements2016-10-282-0/+21
| | | | | | | | | | | | | | 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>
* runtime, cmd/trace: track goroutines blocked on GC assistsAustin Clements2016-10-283-4/+11
| | | | | | | | | | | | | | | | | | 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>
* runtime, cmd/trace: annotate different mark worker typesAustin Clements2016-10-286-7/+13
| | | | | | | | | | | | | | | | | | | | | | 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>
* cmd/trace: fix a runnable goroutine count bugHyang-Ah (Hana) Kim2016-10-112-43/+49
| | | | | | | | | | | | | | | | | | | | | 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>
* cmd/trace: label mark termination spans as suchAustin Clements2016-10-071-2/+2
| | | | | | | | | | | 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>
* cmd/trace: move process-wide GC events to their own rowAustin Clements2016-10-071-0/+3
| | | | | | | | | | | | | | | | | | | | | | | | 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>
* internal/trace: fix analysis of EvGoWaiting/EvGoInSyscall eventsDmitry Vyukov2016-08-191-0/+2
| | | | | | | | | | | | | | | | | | | 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>
* internal/trace: err if binary is not supplied for old traceHana Kim2016-06-162-7/+22
| | | | | | | | 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>
* internal/trace: fix event ordering for coarse timestampsDmitry Vyukov2016-04-241-1/+1
| | | | | | | | | | | Arm arch uses coarse-grained kernel timer as cputicks. As the result sort.Sort smashes trace entirely. Use sort.Stable instead. Change-Id: Idfa017a86a489be58cf239f7fe56d7f4b66b52a9 Reviewed-on: https://go-review.googlesource.com/22317 Run-TryBot: Dmitry Vyukov <dvyukov@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Austin Clements <austin@google.com>
* runtime/trace: test detection of broken timestampsDmitry Vyukov2016-04-241-0/+15
| | | | | | | | | | | | | | | | 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>
* runtime: use per-goroutine sequence numbers in tracerDmitry Vyukov2016-04-233-98/+396
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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>
* runtime: fix description of trace eventsDmitry Vyukov2016-04-221-4/+4
| | | | | | Change-Id: I037101b1921fe151695d32e9874b50dd64982298 Reviewed-on: https://go-review.googlesource.com/22314 Reviewed-by: Austin Clements <austin@google.com>
* internal/trace: fix int overflow in timestampsDmitry Vyukov2016-04-122-1/+55
| | | | | | | | Fixes #15102 Change-Id: I7fdb6464afd0b7af9b6652051416f0fddd34dc9a Reviewed-on: https://go-review.googlesource.com/21730 Reviewed-by: Austin Clements <austin@google.com>
* internal/trace: support parsing of 1.5 tracesDmitry Vyukov2016-04-116-88/+287
| | | | | | | | | | | | | | | 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>
* internal/trace: fix a typo in error messageDmitry Vyukov2016-04-101-1/+1
| | | | | | Change-Id: Id79eaa6d49dae80c334c7243b0a5bbcdcb9397d3 Reviewed-on: https://go-review.googlesource.com/21758 Reviewed-by: Mikio Hara <mikioh.mikioh@gmail.com>
* runtime: emit file:line info into tracesDmitry Vyukov2016-04-081-107/+67
| | | | | | | | | | | | 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>
* all: use bytes.Equal, bytes.Contains and strings.ContainsDominik Honnef2016-04-011-1/+1
| | | | | | | 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>
* all: make copyright headers consistent with one space after periodBrad Fitzpatrick2016-03-011-1/+1
| | | | | | | | | | | | | | | | | | | | | | 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>
View Lorry Controller Status