Hacker News Reader

Comment by jeffbee | Hacker News Reader

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.

View on HN

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.

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.

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).

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.

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

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

Reply on news.ycombinator.com