Enriching Log Messages Using Go Contexts | Hacker News Reader

Enriching Log Messages Using Go Contexts

cockroachlabs.com

10 pointsorangechairs6 comments

Consider switching to entirely structured logs! It's awesome and it'll make the DB much easier to operate! See https://docs.google.com/presentation/d/1KciJt-groC22smVgCg4T...

Thanks! Yes, I expect we will be moving in that direction before too long. It will work well with log tags which are already key-values. Plus most of our messages make it into traces and OpenTracing is switching to a KV interface as well.

What worries me about this is performance. Contexts are linked lists and adding a new value to log will add a new node to this list, slowing down all future operations involving the context. I didn't look at the implementation, but I, at least, couldn't come up with a design that doesn't suffer from this, when I last thought about it. What makes matters worse is, that the logging layer is wrapped around the context in a pretty early stack frame; so every logging statement will need to traverse the whole context list, slowing down the overhead from logging even further than it already is.

So, did you look into this? Does Performance suffer?

Cockroach Labs employee here - the implementation only uses a single context key, so traversing the context linked list is only necessary when the context in hand is a derivative of the annotated context (e.g. obtained via WithTimeout or WithCancel), which is relatively uncommon in practice.

https://github.com/cockroachdb/cockroach/blob/6b0698f/pkg/ut...

Yeah, I thought about that and it definitely is an improvement, but IMHO it still suffers similar problems. In practice, you won't just have logging; you'll add grpc Metadata, user info and whatnot and each thing will slow down all the other things. Is my intuition. I'm skeptical of saving any data in context, for that reason (and this skepticism has prevented me from finishing my ctx-logging-package, that does exactly what you describe :) ).

I'd just like to see good'ol'benchmarks that this is not a problem, before I trust the Context for data :)

In the majority of cases, the current layer would have added a log tag to the Context, so looking up the log tags structure will be immediate. On the other hand, we also use OpenTracing and we do have to go through the hierarchy to find the current Span, which will be slower with deep hierarchies.

The other thing to consider is that logging a message carries other costs, so we can't go crazy with very frequent log messages anyway. In our case the message usually also makes its way into an OpenTracing span and that involves memory allocation and/or data copying. My guess is that going through a few linked Contexts is not a big deal, comparatively speaking.

I don't have the kind of benchmark that you are looking for (with vs without using Context), but I can tell you that in the workloads we looked at, tracing was taking a few percentage points (1-2%) of CPU usage, and I don't think a significant part of that was in Context code.

Finally, Context is an interface, so if need be, we can make our own Context implementation that always stores the frequently looked-up things (like log tags, tracing Spans) to short-circuit that cost.

Reply on news.ycombinator.com