Go: runtime/trace: implement user events

Created on 5 Aug 2016 · 15Comments · Source: golang/go

https://golang.org/s/go15trace specifies user events:

Runtime/pprof package also exposes a set of functions for emission of user events:
package pprof
func TraceEvent(id string)
func TraceScopeStart(id string)
func TraceScopeEnd(id string)

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.)

NeedsFix early-in-cycle help wanted

Source

FiloSottile

Most helpful comment

Was this done in Go 1.11?

I see https://godoc.org/runtime/trace#hdr-User_annotation

nhooyr on 11 Sep 2018

👍2

All 15 comments

@aclements

dvyukov on 5 Aug 2016

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.

aclements on 9 Aug 2016

Yes, I plan to work on it for go1.8 but it's possible we end up with slightly different API.
Will update this issue soon with the plan we are thinking about. @matloob

hyangah on 10 Aug 2016

This is too late for 1.8.

quentinmit on 13 Oct 2016

@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.

rakyll on 15 Jul 2017

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.)

aclements on 15 Jul 2017

I were talking about the possibility of simply using the existing profiler labels as the user spans

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.

rakyll on 15 Jul 2017

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.
That's what we do with goroutines today, using goroutine start function as type.

dvyukov on 15 Jul 2017

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.