Hacker News Reader

Comment by Spivak | Hacker News Reader

Structured logging is just tracing but less powerful. "Context" and "binds" are just poor-man's spans. If you're going to go through the effort to redo your whole application's logging infrastructure just bite the bullet and use OpenTelemetry.

Edit: Good lord people, set the collector to never sample and use one of the many file exporters and you get completely bog standard logs but with a huge amount of work already done for you and enough context to follow complicated multi-threaded/multi-process programs without making your head spin.

View on HN

I think there's room for both.

Tracing is usually sampled, or much more time limited, and aggregation tooling isn't nearly as good compared to logs with most providers. Much better for deep dives into a narrow context. For a single request drilldown or aggregated performance/error metrics, tracing every time.

Structured logging tends to give you rich search against broader contexts (e.g. long spans of time, many requests in aggregate, random non performance/error attributes you may care about) without the same concerns of data cardinality.

I felt nowhere near the same power with tracing tooling for random broad context as I've had with e.g. Splunk for logs. That's not to say you can't somehow have the best of both worlds, but I haven't seen it in the ecosystem just yet.

Indeed. For those unfamiliar, take a quick read of https://github.com/open-telemetry/opentelemetry-specificatio...

There are a few concepts to understand, but instrumenting it right from the start is valuable as it grows into a bigger system. Being a cross-cutting concern, the more code that standardizes on this the more useful it will be.

So much this. What’s important to know is that structured logging is as expensive as tracing. If you are forced into the cost of a trace span for every message, you won’t do much logging. Maybe this makes sense to Python programmers to whom a few microseconds here and there don’t seem significant, but to C++ programmers it is pure lunacy. The cost of informational logging with something like glog or spdlog can be as little as a few CPU cycles.

I don't see why basic structured logging would be more significantly more expensive or complex that unstructured logging.

In the simplest case you could just output a sequence of values (for example as a csv, or one json array per line), instead of an interpolated string. The size and CPU overhead of this approach is minimal, but makes it much easier and more robust to parse the log afterwards.

Such basic structured logging is quite similar to what the article proposes in "Separate parameters and messages", but more consistent and unambitious if one of the arguments contains your separator character.

Correctly and safely serializing to CSV and JSON is more overhead than spitting out bytes. It's also easier to spit or ingest bytes as a stream—yes, there are tools that understand streams of json objects, but you still have to have all the data in memory at once for a given record, to serialize it, and then you've basically got it in memory twice at the same time (original + serialized text). Your minimum record size to consider becomes "this entire object" rather than "this field". You've also now got the code for CSV or JSON serialization in memory.

You can json or csv encode data in a streaming manner, you just need to escape some special characters (only " for csv) and add a separator. But I never worked on an application where log records were big enough for streaming to make sense.

If you want to preserve the "one line = one record" property typically expected from logs, standard csv will not be suitable (since it doesn't escape linebreaks), but json without unnecessary linebreaks will handle that (known as json-lines).

Serializing is very fast, and ingesting JSON as a stream is trivial when it's newline delineated. No one emits a giant array of json log objects, they emit a stream of newline delineated json.

You almost certainly also have it in memory more than twice since you're copying a buffer out to IO.

If you care about record size use protobuf, compression, backend parsers, etc.

Unless we're talking about something performance critical up front like an embedded system, odds are by the time an organization is going to care about logging performance overhead, they probably already have a few engineers dedicated to just optimizing logging.

Of course some developers may just go ahead and create a JSON/CSV string from scratch, which is about as safe as string interpolation instead of parameter bindings for SQL statements /s. But provided they're using a proper JSON/CSV/proto object builder library that uses String references, no data is going to get copied until a logging component needs to write it to a file or a network buffer. Therefore the only overhead are the pointers that form the structure.

Wrong. Structured logging in C++ done right [0] is the most efficient you can do. Plus you get all mentioned benefits.

[0] https://youtu.be/FyJI4Z6jD4w

Structured logging is just taking whatever information you already intended to log anyway and giving it a consistent structure. Ie, instead of

"$TIMESTAMP $LEVEL: Hey look index $INDEX works!"

you have

$TIMESTAMP $LEVEL $FORMATTER $MSG $INDEX

I'm quite intentionally drawing a parallel to `echo` vs `printf` here, where printf has an interface that communicates intended format while echo does not.

The only overhead of structured logs done right is that you need to be explicit about your intended formatting on some level, but now with the bonus of reliable structure. Whether you use glog or spdlog or whatever is somewhat inconsequential. It's about whether you have an essentially unknown format for your data, having thrown away the context of whatever you wish to convey, or whether you embed the formatting with the string itself so that it can later be parsed and understood by more than just a human.

If you're concerned about the extra volume of including something like "[%H:%M:%S %z] [%n] [%^---%L---%$] [thread %t] %v" on every log entry, then you use eg (in GLOG equivalent for your language) LOG_IF, DLOG, CHECK, or whatever additional macros you need for performance.

If I'm wrong or just misunderstanding, please do correct me.

LOG_IF and VLOG, and related concepts from other libraries, have their places but I don't consider not logging to be a solution to expensive logging. In fact, that was my whole original point.

With structured logging the outputs may be trivial in which case the compiler can do a good job. But if you are inserting a std::string into a log line and your log output format is JSON, there's nothing the compiler can do about the fact that the string must be scanned for metacharacters and possibly escaped, which will be strictly more costly than just copying the string into the output.

Please understand my line of inquiry is sincere and not intended to be read as bad-faith-argumentative. I say this only because tone is so hard to convey.

Anyway.

Isn’t the choice of eg JSON-string vs any other string format somewhat beside the point? Wouldn’t you either 1) need to scan for metacharacters or 2) NOT need to scan for metacharacters, regardless of whether your log is structured or unstructured, at time of output?

Ignoring for a moment the additional cost per character of outputting additional data, but ignoring nothing else in the scenario, wouldn’t something like, for example:

“My index is {index}␟index=5”

cost the same to output as:

“My index is 5”?

It seems to me that the cost of interpreting the formatting doesn’t need to be paid until you wish to read the log message, which presumably you don’t strictly need to do at all until you actually care about the content of the message, or at the very least can defer the cost until a less critical moment, or do some “progressive enhancement” dependent on some set of pre-requisite conditions.

Logging is significantly cheaper than tracing to maintain in a usable state.

Maybe it’s just a budget pathology, but we sample our traces. Browsing the available traces can be informative, but you can’t just pull a trace for an arbitrary request. We do keep and index all the logs (for a few days).

> Structured logging is just tracing but less powerful.

That may be the case, however is what you have now is "logging", I would 100% recommend the incremental upgrade to "structured logging".

Reply on news.ycombinator.com