x/net/trace: add Trace.String()

[petermattis]

Currently, the only way to view a trace is to visit the /debug/requests endpoint. This is nice, though impermanent. An application might want to log a trace for a slow request for a more permanent record. I'd like to add Trace.String() as a mechanism for doing this along with Trace.SensitiveString(). Alternately, a single Trace.LogString(sensitive bool) could suffice.

[ianlancetaylor]

CC @dsymonds

[dsymonds]

It's not obvious that this is useful. Traces are a sizable object; note that net/http.Request doesn't have a String method either. A trace also collapses the data stored in it when too many events are recorded on it, so it's already somewhat impermanent.

[dsymonds]

An alternate way of looking at this issue: the x/net/trace package is designed for observing a running server. It is not designed as a mechanism for permanent logging. That should be something separate, with its own considerations and trade-offs.

I think I've convinced myself that there isn't something useful to do here, so I'm going to close this feature request. I'm open to counter-arguments.

[petermattis]

Perhaps I'm misremembering, but I thought the traces displayed on requestz were the same traces written to BINARY_TRACE logs and consumed by dapper for analysis. Maybe a String method is not the appropriate way to expose the trace data for external consumption. I'm pretty sure traces inside Google have an associated proto. I was initially thinking a String method would be simpler and more palatable, but I'd also be happy with a Proto method which serialized the trace to a protobuf.

I could have sworn that C++ traces (at Google) allowed outputting the trace to a string. My mind might be playing tricks on me. It's been years. I'm mildly surprised that you jumped to the conclusion so quickly that there is nothing useful to do here as right now the trace info seems entirely locked up within the x/net/trace package with no way to access other than through an http endpoint. Tying the trace data to the lifetime of a process severely limits its utility. For example, I can't easily run a nightly benchmark and collect traces for later analysis. (Yes, I can crawl the http endpoint at the end of the benchmark, but that is not what I would call easy).

[dsymonds]

No, requestz and the binary logs contained substantial overlap, but they're different code paths and have different purposes. It's also different across languages.

A Proto method to generate a proto might be okay, though that should be decided across languages too. There might be something suitable for gRPC traces, but note that x/net/trace isn't RPC-specific either.

I didn't jump to a quick conclusion. I've been thinking about this code for several years. I just revised my previous thinking on the matter. I don't think there's much in the way of trace-specific information in the trace; all its content comes from outside the package, so those places can simply record the information in a different place too.

[petermattis]

Yes, all of the trace content comes from outside of the trace package, but x/net/trace is a synchronization point. Outputting the trace content to two (or more) systems seems wasteful and burdensome. Already grpc has to create a new context to store the trace in. If there is some other tracing mechanism for outputting to a log would grpc have to create another context (using context.WithValue) for that trace? And every grpc user would have to know to output their trace info to both places?

How do I (as a user of grpc and x/net/trace) get access to the trace content that grpc has stored in a trace? Punting the problem to grpc feels like a non-starter to me so I didn't even consider it. Do you think the Go grpc folks would be open to adding instrumentation points for gathering trace content?

[dsymonds]

Like I said, x/net/trace is not RPC-specific, so if you're after RPC-specific information then you're already looking at the wrong part of the puzzle.

grpc-go is indeed weighing up hooks for per-RPC monitoring and instrumentation. See grpc/grpc-go#240 or grpc/grpc-go#335.

[petermattis]

I get that x/net/trace is not RPC-specific, and yet certain traces are RPC-specific as they are created by the RPC system. How do I get the information from RPC-specific traces with information potentially recorded outside of gRPC? Right now x/net/trace is both the recording and reporting mechanism.

I'll read the issues you pointed to in more detail tomorrow.

[petermattis]

grpc/grpc-go#240 is asking for instrumentation hooks in gRPC for metrics monitoring. That's not what I'm after. grpc/grpc-go#335 is asking for something akin to BINARY_INFO logs. Again, not what I'm after.

I'm looking for something like BINARY_TRACE logs (though perhaps not binary). That is, output of RPC trace info and application-level annotations added to traces (created via LazyLog and LazyPrintf). A Trace.String method might not be the appropriate way to expose this data, but I think it deserves to be exposed. Along with whatever mechanism there is to serialize a trace, there would also need to be a hook or some mechanism to know when a trace is finished. Since I'm interested in traces finished by gRPC, that hook or mechanism potentially lives there, but I think the serialize of Traces has to live in x/net/trace.

Btw, in case it isn't clear, I'm willing to implement this if you give guidance on what you find palatable.

[raliste]

Even though x/net/trace was thought as a reporting mechanism, traces are indeed being generated by the implementation.

We are after binary logging as well so we can collect and analyze traces.

Our first naive approach was:

func() {
  tr := trace.New("Helper", "Call")
  // ...
  defer func() {
    tr.Finish()
    traces <- tr
  }()
}

// ...
go func() {
  for {
    tr := <-traces
    sample(tr) // samples and logs
  }
}

However this approach wouldn't work as all the interesting data is within the private trace struct.