
Enriching Log Messages Using Go Contexts - orangechairs
https://www.cockroachlabs.com/blog/enriching-log-messages-using-go-contexts/
======
AYBABTME
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...](https://docs.google.com/presentation/d/1KciJt-
groC22smVgCg4TfJXqCUAA6D4c6NRdKBIkIHM/edit?usp=sharing)

~~~
radub
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.

------
Merovius
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?

~~~
tdrd
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...](https://github.com/cockroachdb/cockroach/blob/6b0698f/pkg/util/log/log_context.go#L35)

~~~
Merovius
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 :)

~~~
radub
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.

