Tracing keeps entire requests in memory, doesn’t truncate

[stapelberg]

There’s a corresponding TODO (if I understood it correctly) at

grpc-go/trace.go

Line 98 in b0b7afa

// TODO(dsymonds): add stringifying info to codec, and limit how much we hold here?

, but I wanted to open an issue nevertheless, if only so that people can more easily subscribe to it.

Currently, when sending RPCs which contain lots of data (e.g. a scanned document page in https://github.com/stapelberg/scan2drive), grpc accumulates RAM (looking at the process’s resident set size after calling (runtime/debug).FreeOSMemory().

Looking at the /debug/requests page explains where the RAM goes: the messages are included in full in the trace contexts. This not only makes my browser unusable, but also wastes a lot of memory.

I think we should truncate these messages and retain only the truncated version.

[bdarnell]

+1. This is affecting CockroachDB. We occasionally send very large messages, which are getting held in GRPC for a long time if we have tracing enabled (these are the only requests to make it in to the larger time buckets, so they aren't getting flushed out by the more frequent smaller requests). We're going to turn tracing off for now, but I'd like to have finer-grained control of tracing. We've found the connection-level tracing very useful, but the message/stream-level tracing is less useful to us and much more expensive. I'd like to be able to turn off the logging of message bodies. (especially because they're often hidden behind [redacted] - it took me a while to realize that there was this hidden cost).

[iamqizhao]

We are working with another team in Google on replacing the existing tracing. Stay tuned.

[bdarnell]

Any update on this?

[stapelberg]

More than a year has passed. What’s the current status? Flying blind is killing one of my biggest motivations to use gRPC in the first place.

[dfawley]

We recommend disabling tracing in gRPC (grpc.EnableTracing=false) and using the stats handlers to record this data instead. We would like to implement a library that provides integration with x/net/trace via the stats interface, but don't have the bandwidth to do this any time soon.

[dfawley]

After more deliberation, we decided that truncating the messages should be easy and shouldn't be too controversial, so we will just do that for now and file a separate issue to track the implementation of tracing through the stats API.

[dfawley]

...and after the first attempt in #1508, we realized it's very difficult to fix the memory usage problem. To truncate the message before storing it, we must first (s)print it -- but in most cases we'll never display the message, which is why the string method is evaluated lazily. The best I believe we can do without changing what we render in the tracing (e.g. omit the message contents) is to truncate the message when displaying it to protect the browser when it renders them. In theory we could truncate the binary-serialized message when storing it, but I don't believe the Go protobuf library handles truncated messages, so we wouldn't be able to render it in text form later if we did that.

We'll also be disabling tracing by default to prevent this problem from impacting users that don't actually need tracing.

#1509

[stapelberg]

Thanks for looking into this!

In theory we could truncate the binary-serialized message when storing it, but I don't believe the Go protobuf library handles truncated messages, so we wouldn't be able to render it in text form later if we did that.

This is not what I observe: https://play.golang.org/p/u9xZoYLx6J results in:

2017/09/08 18:06:23 unexpected EOF
2017/09/08 18:06:23 res: {Path:[foo bar baz]}

i.e., proto.Unmarshal returns an error, but as a side-effect it also fills in the message as good as it can.

I think it’s safe to unmarshal a truncated message and display the result textually.

[dfawley]

That's encouraging. So maybe the tracing implementation that is based on the stats handler interface can do something a little smarter. #1510

[dfawley]

#1508 adds truncating of messages. #1510 should include reducing total allocations re: the previous 3 comments.