runtime/trace: implement user events #16619
Comments
|
For reference, there's been a lot of discussion about the user events API since the original proposal here: https://go-review.googlesource.com/c/8552/3/src/runtime/trace/trace.go Also, user events came up in today's meeting with @hyangah. |
|
Yes, I plan to work on it for go1.8 but it's possible we end up with slightly different API. |
quentinmit
added
the
NeedsFix
|
This is too late for 1.8. |
bradfitz
added
early-in-cycle
|
@hyangah, what's the status of this? This probably needs a proposal first, I already have background and opinions of this one and can create a proposal if no one is actively working on it. |
|
I have an old prototype of user events at https://go-review.googlesource.com/c/34031/. No effort was made to define a good API, but that could be a useful starting point for an implementation if we decide on an API. Earlier today @heschik, @rhysh, a few others who's usernames I don't know, and I were talking about the possibility of simply using the existing profiler labels as the user spans, since they often contain exactly the request information you might want to include in a user span. (I'm not personally convinced this is a good idea, but writing it down for the record.) |
I don't think this is a good idea. There is an obvious possibility to annotate spans with profiler labels but we shouldn't assume they are representing the spans' themselves. In tracing, one of the fundamental features is to give to user the flexibility to be able to mark the sections they are interested in and find statistically meaningful. |
|
FWIW is would be useful if we could understand span type, i.e. these spans are of type A (say, request processing), while these are of type B (say, database accesses). Then we could automatically infer cases of tail latency and give explanation as to why a particular span takes so long. For example, this span is the longest of its type, it has comparable with other spans of the same type cpu time, scheduler latency and network wait time, but was blocked on mutexes 10x longer. |
|
I think I get why having profiler labels create spans is undesirable, but I don't see any reason not to propagate the profiler labels to the execution trace. Concretely, just emit a trace event whenever a goroutine's labels change, and the trace viewer can attach them on all of the slices (rectangles in the UI) it emits to the JSON. |
|
I compiled my thought in https://goo.gl/iqJfJ3 |
|
Change https://golang.org/cl/59572 mentions this issue: |
|
Something related for the reference - some of us are doing user-level Linux-style traceevents/tracepoints in Go: https://lab.nexedi.com/kirr/go123/blob/c0f14991/tracing/tracing.go https://lab.nexedi.com/kirr/go123/commit/3cf17be3 |
|
Change https://golang.org/cl/63274 mentions this issue: |
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>
|
Was this done in Go 1.11? |
|
Why isn't there an average for each task? |
https://golang.org/s/go15trace specifies user events:
But there is no implementation at this time.
Those would be invaluable to properly debug latency problems.
(According to @dvyukov there is no one actively working on it, so I might give it a try.)
The text was updated successfully, but these errors were encountered: