This post falls into a common trap; conflating logging with metrics.
Log interesting things, where interesting is defined as context outside what the "happy path" execution performs.
Collect and make available system metrics, such as invocation counts, processing time histograms, etc., to make available what the post uses log statements to disseminate same.
I agree with this. Logging, as well as metrics and tracing, are such hard topics for me to wrap my head around though.
From the log consumer (person) perspective, you'd want logs to provide you with sufficient information when troubleshooting. But since trouble usually happens when things go wrong in unexpected ways, the logging likely won't be well aligned to emit the right info for you to figure out what's going wrong exactly. What then, are you supposed to log the entire application state and every change to it? But then that's way too expensive, and there's a decent chance you might just drown in the noise instead. So you're left with this half artform half science type deal.
One thing I'm grateful for is that over the years most everything now logs in JSON lines at least. I just wish there was a standardized, simple way to access all the possible kinds of JSON objects that might be emitted into the logs. A schema would be a good start, but then I can immediately see ways how that would be quickly rendered lot less useful early on (e.g. "this and that field can contain some other serialized JSON object, good luck!").
One way to reframe this is: "as a user [of the logs], what might I want to know?"
In my experience, this post is often right (and the logs are often wrong). There's a tendency to either log too much or log too little - if only a few items are getting processed, it's fine and maybe even good to log all 7 of them.
But if many, many are getting processed - you'll experience semantic overload as a reader of the logs. What you want is a compressed form
Logging per time interval can be a very handy approach. In my work, we've settled on a hybrid approach - calculate in real time how often things are happening and then log the number of things that have happened, but at a rate that is roughly one log every N seconds.
This takes some more engineering up front but is remarkably often what a log reader actually wants.
The practical problem with logging by time is that it's not resource constrained: holding N seconds of logs, even when each line is a bounded size, takes potentially unlimited memory. Logging 'by count' used a bounded amount of memory, and is easy to implement with a fixed size array in memory.
log all major logical branches within code (if/for)
if "request" span multiple machine in cloud infrastructure, include request ID in all so logs can be grouped
if possible make log level dynamically controlled, so grug can turn on/off when need debug issue (many!)
if possible make log level per user, so can debug specific user issue
The only one I'll add is: If your logs are usually read in a log aggregator like Splunk or Grafana instead of in a console or text file, log as JSON objects instead of lines of text. It makes searches easier.
I wonder how do they log mission critical things in general. For instance, how often does a flight data recorder (FDR) log every state of mechanical components? Surely, they can't wait until something "interesting" to happen, right?
Even better: log absolute total counts of received and finished events. You can easily extract the rates from that, and you'll know if the process builds up a lot of simultaneous processing, and you can more easily compute longer-term averages, and you know if it is starved for work or resources, etc.
No, please don't use logs to deduct whether your application is running.
Provide an endpoint which presents health information and use infrastructure-level metrics.
I think count based logging works really well for batch processing jobs where each item is a fairly constant amount of work. The log shows the time you started and prints another line (with the time) for each 1% of the batch. You can see the progress and guess when it will be done.
The human who is debugging an issue can see when we started, see that some processed successfully, see regular progress through the batch, then see that the 58th percentile batch hasn’t completed and that’ll be where the problem is.
The main benefit over the time based logging is that the code is much simpler, and the log output is simpler too.
There are even libraries like tqdm that do this for you in one line of code.
Logging is an exercise in solving problems of future you.
We don't log just to have records of everything, we log to solve future questions.
I'm working on a system that generates huge numbers of log entries and have settled on a short term solution to over log everything.
Once a log entry has persisted, I'm using it as a 'Bronze Layer' in a typical Medallion Model and will then filter that log data up into Silver and Gold layers so I can have billing, reporting, dashboard metrics being lifted out of the verbose logs.
Not sure what I'll do with the verbose Bronze Layer logs maybe cold store them somewhere, but it's interesting to experiment with progressive aggregation of logs to hopefully purge and dispose of the raw log data as fast as we can extract value.
There is an additional benefit to throttling by time, it is a lot easier to do it efficiently in multithreaded environments.
If you log by count, you need a global counter for that event (you could do thread-local, but then your logging volume would depend on the number of threads). If the code path is hot (which may be the case if you want to throttle your logs) multiple threads will contend on the increment, and that can be very expensive.
If you log by time, you just need a load and a clock read (on Linux, `CLOCK_MONOTONIC_COARSE` is a handful of ns and the resolution is enough for this purpose), and only need synchronization (a compare-and-swap) when the timer expires, so threads virtually never interfere with each other.
It should be both. A heartbeat monitor can log information at periodic events while warnings, errors and other high priority events are logged as soon as they occur. All log entries should be time-stamped regardless of the logging frequency.
the OP wrote "This is a simple concept, but I've never seen it written down before." Putting on my tin-foil hat:
Maybe that's because predictable log volume isn’t in the vendor’s interest. Time-based logging makes usage easier to reason about. Bursty, count-based logs? Much harder to estimate—much easier to monetize.
Metrics should be emitted in separate stream and never by logs outside corner cases. Logs should be used to determine WHY the system is having issues but never IS the system having issues.
Log alerting is a fools errand that looks like a great idea at start but quickly becomes a sand trap that will drive future people crazy and at scale, will overwhelm systems.
Why is log alerting bad idea?
Every log becomes a metric point that must be dealt with. Therefore, the logging system must be kept operational and error free. However, due to other problems below, this system quickly becomes a beast of it's own.
Logs are generally much bigger then KV of <Metric> <Value> so there ends up being a ton of filtering going on in logging system, adding to the load.
Logging system probably does not understand rates so you end up writing gnarly queries to be like "Is this first unhandled exception?" in 10m or my 50th in 10m. Query in Prometheus is much much simpler.
Each language logging library handles things in different way so organization must be on point to either A) Keep log format the same between all different languages. B) Teach the logging system how to manipulate each log into format that can be handled by alerting system. Obviously A causes massive developer friction and B causes massive Ops friction.
Finally, I find people doing logging tend not handle exceptions as well because they can just trust logging system to alert them on specific problem and deal with it manually.
So for future Ops person who has to deal with your code, I'm begging you, import prometheus_client.
I think I'm missing something. I am not a SWE but when I'm looking at logs I'm not really all that interested in the number of events, but instead I want to know what those events are. If I need the number, that's something that my SEIM or BI should counting.
I think there's a bug in the sample code, because the claim is to have a "consistent log rate": In the example, "read_event_from_queue()" should be blocking. If there are no items read from the queue within the given time interval, the logging part will never trigger, so the time-based logging does not have a consistent log rate.
Besides the (potential) bug, it is a cool idea, if emitting metrics is not an option.
If you want to know if an application is running, implement health checks. I hope I never have to deal with the pattern suggested in this article in a production system.
I think, if you work with logging long enough this becomes common sense at some point. Consider when logging backend performance or subscription gets hit by bursts - e.g. an unlikely code path gets repeatedly hit that logs an error or in the worse case an exception trace. With logging every X occurrence you reduce the total amount, but don't have control about the overall rate. With logging every X seconds, you can manage the rate better, which is useful depending on the logging backend performance or subscription.
I think "time based logging" is a bit of an anti-pattern, as that's LITERALLY a metric. The thrust of this is "sample at a consistent rate" which, yeah sample your numbers at a consistent rate. But also, probably don't use logs for this, probably use a metrics tracking system.
Often logging backends have a sampling rate to take care of this for you. As it is almost certainly better to setup a buffer in your logging layer and deal with this there, than to try and do this everywhere in your code.
28 comments
[ 3.4 ms ] story [ 41.9 ms ] threadLog interesting things, where interesting is defined as context outside what the "happy path" execution performs.
Collect and make available system metrics, such as invocation counts, processing time histograms, etc., to make available what the post uses log statements to disseminate same.
From the log consumer (person) perspective, you'd want logs to provide you with sufficient information when troubleshooting. But since trouble usually happens when things go wrong in unexpected ways, the logging likely won't be well aligned to emit the right info for you to figure out what's going wrong exactly. What then, are you supposed to log the entire application state and every change to it? But then that's way too expensive, and there's a decent chance you might just drown in the noise instead. So you're left with this half artform half science type deal.
One thing I'm grateful for is that over the years most everything now logs in JSON lines at least. I just wish there was a standardized, simple way to access all the possible kinds of JSON objects that might be emitted into the logs. A schema would be a good start, but then I can immediately see ways how that would be quickly rendered lot less useful early on (e.g. "this and that field can contain some other serialized JSON object, good luck!").
In this particular example, I agree with others: this is a case for metrics. "Log errors, metric successes[0]."
0: success events (a bit more than a log typically) may be important, especially if tied to something you charge for.
In my experience, this post is often right (and the logs are often wrong). There's a tendency to either log too much or log too little - if only a few items are getting processed, it's fine and maybe even good to log all 7 of them.
But if many, many are getting processed - you'll experience semantic overload as a reader of the logs. What you want is a compressed form
Logging per time interval can be a very handy approach. In my work, we've settled on a hybrid approach - calculate in real time how often things are happening and then log the number of things that have happened, but at a rate that is roughly one log every N seconds.
This takes some more engineering up front but is remarkably often what a log reader actually wants.
The only one I'll add is: If your logs are usually read in a log aggregator like Splunk or Grafana instead of in a console or text file, log as JSON objects instead of lines of text. It makes searches easier.
The human who is debugging an issue can see when we started, see that some processed successfully, see regular progress through the batch, then see that the 58th percentile batch hasn’t completed and that’ll be where the problem is.
The main benefit over the time based logging is that the code is much simpler, and the log output is simpler too.
There are even libraries like tqdm that do this for you in one line of code.
Metrics enable the ability to aggregate concepts into some kind of meaning.
Meaning can then have alerts associated to them.
You cannot create metrics on things you don’t know, which is why logging is the base.
We don't log just to have records of everything, we log to solve future questions.
I'm working on a system that generates huge numbers of log entries and have settled on a short term solution to over log everything.
Once a log entry has persisted, I'm using it as a 'Bronze Layer' in a typical Medallion Model and will then filter that log data up into Silver and Gold layers so I can have billing, reporting, dashboard metrics being lifted out of the verbose logs.
Not sure what I'll do with the verbose Bronze Layer logs maybe cold store them somewhere, but it's interesting to experiment with progressive aggregation of logs to hopefully purge and dispose of the raw log data as fast as we can extract value.
If you log by count, you need a global counter for that event (you could do thread-local, but then your logging volume would depend on the number of threads). If the code path is hot (which may be the case if you want to throttle your logs) multiple threads will contend on the increment, and that can be very expensive.
If you log by time, you just need a load and a clock read (on Linux, `CLOCK_MONOTONIC_COARSE` is a handful of ns and the resolution is enough for this purpose), and only need synchronization (a compare-and-swap) when the timer expires, so threads virtually never interfere with each other.
Maybe that's because predictable log volume isn’t in the vendor’s interest. Time-based logging makes usage easier to reason about. Bursty, count-based logs? Much harder to estimate—much easier to monetize.
Metrics should be emitted in separate stream and never by logs outside corner cases. Logs should be used to determine WHY the system is having issues but never IS the system having issues.
Log alerting is a fools errand that looks like a great idea at start but quickly becomes a sand trap that will drive future people crazy and at scale, will overwhelm systems.
Why is log alerting bad idea?
Every log becomes a metric point that must be dealt with. Therefore, the logging system must be kept operational and error free. However, due to other problems below, this system quickly becomes a beast of it's own.
Logs are generally much bigger then KV of <Metric> <Value> so there ends up being a ton of filtering going on in logging system, adding to the load.
Logging system probably does not understand rates so you end up writing gnarly queries to be like "Is this first unhandled exception?" in 10m or my 50th in 10m. Query in Prometheus is much much simpler.
Each language logging library handles things in different way so organization must be on point to either A) Keep log format the same between all different languages. B) Teach the logging system how to manipulate each log into format that can be handled by alerting system. Obviously A causes massive developer friction and B causes massive Ops friction.
Finally, I find people doing logging tend not handle exceptions as well because they can just trust logging system to alert them on specific problem and deal with it manually.
So for future Ops person who has to deal with your code, I'm begging you, import prometheus_client.
Besides the (potential) bug, it is a cool idea, if emitting metrics is not an option.
If you want to know if an application is running, implement health checks. I hope I never have to deal with the pattern suggested in this article in a production system.