summaryrefslogtreecommitdiff
path: root/src/internal/trace/parser.go
Commit message (Collapse)AuthorAgeFilesLines
* 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>
* runtime/trace: rename "Span" with "Region"Hana Kim2018-04-241-24/+24
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | "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>
* 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: 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-151-1/+40
| | | | | | | | 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-201-12/+20
| | | | | | | | | | | | | | | | | | | | 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-291-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-191-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-101-93/+111
| | | | | | | | | | | | | | | | | | | | 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-281-0/+2
| | | | | | | | | | | | | | 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-281-3/+5
| | | | | | | | | | | | | | | | | | 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-281-5/+11
| | | | | | | | | | | | | | | | | | | | | | 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: 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-161-6/+19
| | | | | | | | 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>
* 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-231-94/+114
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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-121-1/+3
| | | | | | | | 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-111-86/+228
| | | | | | | | | | | | | | | 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>
* runtime,internal/trace: map/slice literals janitoringDidier Spezia2015-09-111-1/+1
| | | | | | | | | | 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>
* runtime/trace: report negative frequency as a time-ordering problemRuss Cox2015-07-301-2/+4
| | | | | | | | 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>
* runtime/trace: record event sequence numbers explicitlyRuss Cox2015-07-291-27/+47
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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>
* internal/trace: fix fuzzer crashersDmitry Vyukov2015-07-181-7/+19
| | | | | | | | | | | | | 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>
* internal/trace: add comment for stable sortDmitry Vyukov2015-07-021-0/+2
| | | | | | | | | 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>
* internal/trace: stable sort eventsDmitry Vyukov2015-07-021-1/+1
| | | | | | | | | | | | | | | | | | | | | 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>
* all: fix misprints in commentsAinar Garipov2015-06-111-2/+2
| | | | | | | | | | 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>
* internal/trace: don't assume GC will start and end on same PAustin Clements2015-04-101-6/+6
| | | | | | | | | | | | | | | | 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>
* runtime: fix tracing of syscall exitDmitry Vyukov2015-04-101-6/+30
| | | | | | | | | | | Fix tracing of syscall exit after: https://go-review.googlesource.com/#/c/7504/ Change-Id: Idcde2aa826d2b9a05d0a90a80242b6bfa78846ab Reviewed-on: https://go-review.googlesource.com/8728 Reviewed-by: Rick Hudson <rlh@golang.org> Run-TryBot: Dmitry Vyukov <dvyukov@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org>
* runtime: remove futile wakeups from traceDmitry Vyukov2015-03-171-2/+63
| | | | | | | | | | | | | | | | | | | Channels and sync.Mutex'es allow another goroutine to acquire resource ahead of an unblocked goroutine. This is good for performance, but leads to futile wakeups (the unblocked goroutine needs to block again). Futile wakeups caused user confusion during the very first evaluation of tracing functionality on a real server (a goroutine as if acquires a mutex in a loop, while there is no loop in user code). This change detects futile wakeups on channels and emits a special event to denote the fact. Later parser finds entire wakeup sequences (unblock->start->block) and removes them. sync.Mutex will be supported in a separate change. Change-Id: Iaaaee9d5c0921afc62b449a97447445030ac19d3 Reviewed-on: https://go-review.googlesource.com/7380 Reviewed-by: Keith Randall <khr@golang.org>
* cmd/trace: move goroutine analysis code to internal/traceDmitry Vyukov2015-03-111-8/+11
| | | | | | | | | | | | This allows to test goroutine analysis code in runtime/pprof tests. Also fix a nil-deref crash in goroutine analysis code that happens on runtime/pprof tests. Change-Id: Id7884aa29f7fe4a8d7042482a86fe434e030461e Reviewed-on: https://go-review.googlesource.com/7301 Run-TryBot: Dmitry Vyukov <dvyukov@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Keith Randall <khr@golang.org> Reviewed-by: Andrew Gerrand <adg@golang.org>
* cmd/trace: dump thread id on proc startDmitry Vyukov2015-03-111-2/+2
| | | | | | | | | Augment ProcStart events with OS thread id. This helps in scheduler locality analysis. Change-Id: I93fea75d3072cf68de66110d0b59d07101badcb5 Reviewed-on: https://go-review.googlesource.com/7302 Reviewed-by: Keith Randall <khr@golang.org>
* runtime: remove runtime frames from stacks in tracesDmitry Vyukov2015-03-101-2/+2
| | | | | | | | | | | Stip uninteresting bottom and top frames from trace stacks. This makes both binary and json trace files smaller, and also makes stacks shorter and more readable in the viewer. Change-Id: Ib9c80ccc280504f0e235f867f53f1d2652c41583 Reviewed-on: https://go-review.googlesource.com/5523 Reviewed-by: Keith Randall <khr@golang.org> Run-TryBot: Dmitry Vyukov <dvyukov@google.com>
* cmd/trace: add new commandDmitry Vyukov2015-02-201-0/+662
Trace command allows to visualize and analyze traces. Run as: $ go tool trace binary trace.file The commands opens web browser with the main page, which contains links for trace visualization, blocking profiler, network IO profiler and per-goroutine traces. Also move trace parser from runtime/pprof/trace_parser_test.go to internal/trace/parser.go, so that it can be shared between tests and the command. Change-Id: Ic97ed59ad6e4c7e1dc9eca5e979701a2b4aed7cf Reviewed-on: https://go-review.googlesource.com/3601 Reviewed-by: Andrew Gerrand <adg@golang.org>
View Lorry Controller Status