21 ms·

Log by time, not by count

241 points by JohnScolaro 1y ago

yonran 1y ago
Putting a few important metrics in the logs every 10s is something that the Aerospike datastore also does (https://aerospike.com/docs/database/observe/latency https://aerospike.com/docs/database/observe/latency). This is useful because when you contact support, they run a script to generate a table of historical latencies from the log without depending on you having set up Prometheus, CloudWatch, etc.
dimatura 1y ago
I've found myself adopting this philosophy for a specific use case: monitoring ML training jobs. It's pretty common to see people output training metrics (loss, validation accuracy, etc) every N batches, iterations or epochs. And that does make sense for a lot of reasons, and it's pretty simple to do. But also when you're exploring models that might have wildly varying inference latencies, or using different hardware, or varying batch sizes, or using a differently sized dataset, all of those might end up reporting too infrequently to get an idea of what's happening or too frequently and just spamming too much output. Checkpointing the model every N iterations/epochs/batches has a similar problem - you may end up saving very few checkpoints and risk losing work or waste a lot of time/space with lots of checkpoints. So I've often found myself implementing some kind of monitoring and checkpointing callbacks based on time, e.g., reporting every half an hour, checkpointing every two hours, etc.
AdieuToLogic 1y ago
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.
- JohnScolaro 1y ago
  Thanks for taking the time to reply! I'm relatively new to working on this type of system (large scale, event driven) and half posted because I know there are people on HN way better than me at this, and was curious about their opinions. In the end, what's the difference between a log and a metric? Is one structured, and one unstructured? Is one a giant blob of text, and the other stored in a time series db? At the moment I guess I'm "logging my metrics" with structured logs going into Loki which can then unwrap and plot things. You and the other commenters have given me the vocabulary to dig more into this area on the internet though. Thanks!
  - lelanthran 1y ago
    > In the end, what's the difference between a log and a metric? The goals. The goals of the activity is the difference. The goal of logging is diagnostics and trouble-shooting (when did this break, how often do we see this type of failure, etc). The goal of metrics is to aid in capacity planning (are we close to running out of RAM, do we exceed 80% CPU too often, etc). > You and the other commenters have given me the vocabulary to dig more into this area on the internet though. Read this first; it is a short read (taxonomy of logging, basically): https://www.lelanthran.com/chap10/content.html https://www.lelanthran.com/chap10/content.html
  - nixpulvis 1y ago
    I'm not sure I want to weigh in on "log" vs "metric"... but I did want to add some thoughts on logs in general. If you need to "log" something to give users feedback as the system is running, it may be less of a log and more of a progress or status output. Logs to me are things which happen and I want to be able to trace later, so summarizing or otherwise dropping logs that come in quickly in succession would be a problem. If I need to filter I pipe to grep, otherwise I can just save it all and read through it later. Status messaging, which may be informative about your process is useful, and if its goal is to be observed real-time, then yea. A message or two a second seems like a good goal for consistency. These are just two very different use cases to me. And generally I find the former critical to get right, while the later may be nice to have and may lead to discovery by nature of making it more accessible.
  - 1y ago
- bravesoul2 1y ago
  Metrics are way quicker to query due to aggregations and tend to be more stable as features change. It's good to save metrics for things that remain true under arbitrary aggregations. E.g. sum, count, maximum and avoid things that do not survive aggregations such as percentiles.
- aflag 1y ago
  I thought the post was nice. I've written scripts before where I'd just print by count and be overwhelmed. I should've just used time instead of changing the count number
- delusional 1y ago
  > This post falls into a common trap; conflating logging with metrics. This isn't as much "conflating" as it is constructing an ad hoc metrics subsystem that exports the metrics to the logs. There's no theoretical difference between exposing a prometheus endpoint that's scraped every x seconds and printing the same data to the logs every x seconds.
- jillesvangurp 1y ago
  Filter and aggregate after you log your metrics, traces, log messages, etc.; not before. You can worry about data retention, rollups, and other strategies for limiting data storage separately from the systems that emit the data. At least with the right data stores. I kind of like what opensearch and elasticsearch do for this. In Elasticsearch you have a data stream. You configure it to roll over based on time or data size. Once rolled over, indices are read only; new data appends to the current one. You then can define life cycle policies to decide what to do with the old ones and e.g. move them to cold storage, transform them with rollups, and eventually delete them. With application logging, you typically assign different log levels. Trace and debug are typically disabled in production (or should be). Info can be quite noisy. Warn tends to be repetitive (because developers tend to ignore warnings and will never fix them). Errors should be rare. I have my system configured to start emailing me if errors get logged. An error means something is broken and needs to be fixed. Zero tolerance on errors. When an error happens, all the other log information provides me context. So there's value in retaining that. But only for a few days at best. Long enough to survive a weekend or things like Christmas. But after that it's just noise. I have a hard cut at about two weeks. Some places you need to store stuff longer for ass coverage reasons. Data retention comes at a price of course. I've seen companies log ginormous amounts of data and ignoring all their errors. 30GB per day. Absolutely appalling. Me: it looks like your database layer is erroring non stop (constraint violations and worse); you might want to do something about that. Them, ah no that's just normal we just ignore it (php shop, incompetence was the norm). Me: so how do you know when something breaks?! Them: ......?! My well paid consulting gig was beating some sense into this operation as one of the managers noticed they were spending hundreds of thousands per year on this nonsense. My fee was a rounding error on that. Easiest job ever. But kind of cringe worthy once I started looking into what they were actually doing and why. Mostly it's just, "yeah some guy set that up once and then we never looked at it and he left. What are you going to do?!". There was a lot of that with this company. Just absolutely nobody that even cared about the waste of resources or getting any meaningful feedback from their logging. If that's your team, you need to do something about it. That's your job and your not doing it well. If you need an external consultant to tell you, you might want to reflect on the notion of majorly shaking things up a bit.
- ejs 1y ago
  I built a system for collecting metrics via logs and has worked well for my apps when I don't want to set up a whole separate system for it.
- Too 1y ago
  One exception to this is batch scripts and other cli tools with a clear start and end, like an installer, rsync, curl, dd, etc. Setting up metrics here is way overkill and the user may still be interested in the progress. Easiest made available through logs. Curses UI could be a nice middle ground but also very often overkill.
- jonhohle 1y ago
  I enjoyed our metrics systems at Amazon’s and wrote one with a similar API at Okta and should really look at writing another one to open source. One of the huge missing things in metrics systems, imho, is keeping granular metrics in the context of a business operation and then using late aggregation for trends. Last I looked nearly every metrics systems either logged individual events and and required processing for any rollup or aggregated too early and you couldn’t determine the effect on any individual operation/request. There’s a happy medium where you can get per-request counts, stats, and timing and still roll those up at the host/data center/region/granularity to get higher level trends. Most metrics APIs are incompatible with this idea, however.
  - Baarsgaard 1y ago
    You're likely talking about "wide events" Which is essentially as many dimensions as possible attached to an event. I believe Meta was the one to develop an internal tool for handling this named Scuba.
- kixelated 1y ago
  Absolutely. Logs should be bursty, because they're most useful when debugging rare issues. If you have identical log lines, then that should have been a metric instead. Metrics should be sampled based on frequency, because they deduplicate. I'm a huge fan of logarithmically sampling metrics.
perching_aix 1y ago
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!").
- Joker_vD 1y ago
  > What then, are you supposed to log the entire application state and every change to it? For replayability/state reconstruction, usually it's enough to log the input data and the decisions made upon them i.e. which branches of the if/switch (and things morally equivalent to them e.g. virtual functions and short-circuiting Boolean operators) you've actually taken. > But then that's way too expensive, Yes, it's usually still way too expensive. But when it's not, it does give you information about at what code point exactly the "wrong" decision was made, and from there you can at least start thinking about how the system could get into the state where it would start making "wrong" decisions at this precise point of code — and that usually cuts down the number of possible reasons tremendously.
- cjsawyer 1y ago
  My personal answer to this is logging very little during normal operation and then logging a lot during errors. Depending on the maturity of the system “a lot” might mean the entire state so I can debug afterwords.
- Veserv 1y ago
  Everything is events. The problem is that, as you notice, you frequently encounter situations where there are too many events to handle. Metrics, logging, and tracing are just three different ways to handle that problem. Metrics handles too many events by aggregating them. You handle too many events by squashing them into a smaller number of events that aggregate the information. Logging handles too many events by sampling them. If you have N times as many events as you can handle, take 1 in N of them or whatever other sampling model you want. Tracing is logging, but where you have chains of correlated events. If you have a request started and a request ended event, it is pretty useless to get one without the other. So, you sample at the "chain of correlated events" level. You want 1 in N "chains of correlated events". But, if you have enough throughput for all your events, just get yourself a big pile of events and throw it into a visualizer. Or better yet, just enable time travel debugging tracing so you do not need to even need to figure out how the events map to your program state.
jpgvm 1y ago
If you can can "log by time" then what you need is metrics, not logs.
sethammons 1y ago
Aggregation by time and count together is a normal batching technique and I have used it a lot to scale out multiple parts of many systems. 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.
- smohare 1y ago
  [dead]
ledauphin 1y ago
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.
- kiitos 1y ago
  The "compressed form" of logs you're describing here is really just metrics...
  - ledauphin 1y ago
    it's not, though. sometimes you need actual active logs to tell you that something is progressing.
    - kiitos 1y ago
      You don't need logs for that, you can get it from metrics just fine. Via absolute value counters, or some kind of percentage-complete gauge, either way you can easily see progress over time...
pjz 1y ago
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.
- Thorrez 1y ago
  You're talking about a different scenario than than the article. The article is about a strategy of how to generate a single log line. You're talking about a strategy of how to batch multiple log lines together.
haiku2077 1y ago
Best advice I ever got on logging: 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 - https://grugbrain.dev/ https://grugbrain.dev/ 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.
- sofixa 1y ago
  > log as JSON objects instead of lines of text Or logfmt which is easier to read for humans, lower overhead, and is still structured and supported in at least Grafana/Loki for parsing and queries.
  - haiku2077 1y ago
    Does logfmt allow nesting? I often inckude data structures like dicts/maps, arrays or complex objects in my JSON logs.
- KronisLV 1y ago
  My colleagues love to log as little as possible and most of the projects I’ve seen still treat logs as files instead of event streams that could have some search and filtering and categorization and automated alerting. It’s kind of unfortunate, because for example there’d be pushback against logging branches in code etc., except for trace logs (that others wouldn’t add) that are also off most of the time when problems actually happen. It does help a lot in personal projects though, albeit the limited traffic there kinda minimizes any problems that ample logging might otherwise cause. At least it’s possible to move in the direction of adding some APM like GlitchTip or Skywalking.
  - delusional 1y ago
    I've had colleagues try this. It rarely works. Logging every if end up introducing a huge amount of overhead, both in terms of processing power, but especially in terms of storage. You almost always end up having to filter based on some sort of log level that you then turn off by default in production. The problem with that is that you're now required to reproduce the issue after turning on the logging, and if you already have a reproducer, why not just attach a real debugger? The overlap of "we can reproduce" but "it has to run on the production server" ends up being practically zero.
MinimalAction 1y ago
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?
- AdieuToLogic 1y ago
  > 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? There are different types of logging. What you describe could be defined as an audit log intrinsic to system operation, which is quite a different thing than what the article describes.
  - MinimalAction 1y ago
    Oh, I see. My bad then. Could you expand a bit more?
    - AdieuToLogic 1y ago
      >> There are different types of logging. > Oh, I see. My bad then. Could you expand a bit more? Sure, I'll do my best. The terms "logging" and "logs" are overloaded in the software industry and often used assuming context is known. Below are four examples illustrating same. # Program Logs This type of logging is what the article discusses and is what many developers are most familiar with. Usually, each entry is associated with a level (such as "debug", "info", "error", etc.) and capture state relevant to program execution at the point of log emission during the call tree is evaluation. Usually they are used for postmortem analysis when a problem is discovered. # Audit Logs This type of logging serves to record changes in the persistent representation of key abstractions, often due to regulatory requirements. Your example of "a flight data recorder" is a great exemplar. Audit logs for an entity are often independent of other entities and may not support the ability to replay the changes. # Write-Ahead Logs[0] This type of logging is frequently used as an implementation detail for various database technologies, such as RDBMS's. WAL's are most often employed to address database crash recovery and intimately involved with transaction management. # Event Sourcing[1] While Event Sourcing might not be immediately thought of as a form of logging, it becomes clear it is when considering how the events are stored. Most discussions of Event Sourcing either describe it in terms of an Audit Log (like the referenced article does) or as an "append-only log." 0 - https://en.wikipedia.org/wiki/Write-ahead_logging https://en.wikipedia.org/wiki/Write-ahead_logging 1 - https://martinfowler.com/eaaDev/EventSourcing.html https://martinfowler.com/eaaDev/EventSourcing.html
stephenlf 1y ago
Quick and easy.
kqr 1y ago
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.
Bleibeidl 1y ago
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.
sjducb 1y ago
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.
RHSman2 1y ago
Logging (at scale) is the most important thing to understand reality in your system. At scale, realities are many. 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.
- RHSman2 1y ago
  Btw: logging and the ability to observe systems was the single and most successful act I have done in my career as a Data Product Manager. I have had to fight, do tricks and ‘play the game’ so much. I cannot stress the importance of understanding atomic movements. The cost is high but not as high as the cost of not knowing.
calrain 1y ago
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.
ot 1y ago
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.
- layer8 1y ago
  That still means each thread will do its own separate log call every second (or whatever the period is) instead of all threads aggregating into a single log call.
  - ot 1y ago
    No, the timer is still global (that's why you need the compare-and-swap). But the threads only need to do reads most of the time, and reads do not cause contention. Writes do. It looks something like this (pseudocode): static std::atomic<uint64_t> deadline{0}; auto now = coarse_clock::now(); auto curDeadline = deadline.load(std::memory_order_relaxed); if (now >= curDeadline && deadline.compare_exchange_strong(curDeadline, now + period, std::memory_order_relaxed)) { // Actually log }
    - layer8 1y ago
      Your “actually log” is within one thread. Either the threads all do their separate “actually log”, or they have to synchronize their data into a single shared “actually log”.
      - ot 1y ago
        > Either the threads all do their separate “actually log” But why? Often the purpose is just to log a "been here" signal with some additional details for diagnostics. You don't need to include an accumulation of everything that happened since the last log. All that you care about is that the log happens at most 1/period, say once per second. If you do want to also log some data that accumulates everything that happened, you can accumulate the data in thread-local buffers, and in the "actually log" part collect all the buffers and log them. Since this only happens in the thread that "wins" the CAS, it is still very scalable. This is a very common technique. If you throttle by count, you cannot avoid the contended atomic increment (you can with some sophistication and at the cost of some approximation).
glitchc 1y ago
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.
rco8786 1y ago
it seems like aggregates/metrics are the right tool for this particular thing.
vanschelven 1y ago
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.
stackskipton 1y ago
As SRE/DevOps/Ops whatever, I'm screaming. 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.
- aarmenaa 1y ago
  I've noticed that for some reason developers really like using logs in place of actual metrics. We use Datadog, and multiple times now I have seen devs add additional logging to an application just so they can then create a monitor that counts those log events. I think it's a path of least resistance thing; emitting logs is very easy, and counting them is also very easy. Reporting actual metrics isn't really difficult either, but unless you're already familiar with the system it's more effort to determine how to do it than just emitting a log line, so yeah.
  - chaps 1y ago
    Because when the application is breaking it's good to know why! Logs can be just as ephemeral as metrics -- in many cases, even more so. They're not even mutually exclusive. Where exactly does this anti-logs sentiment come from? Is it because tools like datadog can be lackluster for reading logs across bunches of hosts?
thesuitonym 1y ago
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.
raphting 1y ago
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.
mkl95 1y ago
> Log rate should be consistent 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.
- fgonzag 1y ago
  Yup, he's trying to solve monitoring and logging with the same setup. I don't think I'd appreciate it, but like all the IT horror stories can be probably made to work.
paffdragon 1y ago
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.
lelandbatey 1y ago
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.
taeric 1y ago
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.
- DougN7 1y ago
  Except that you waste CPU cycles preparing the log string and calling the log function only to have it all thrown away.
  - pvorb 1y ago
    At least in the Java world it is common to let the logging framework handle parameter evaluation for you.
    - jdbernard 1y ago
      This feels like one of those "not obvious until you've seen it in production" requirements: any production-ready logging framework should have a mechanism to delay parameter evaluation until after the threshold/destination checks are performed. Most languages have some version of deferred execution (lazy evaluation, thunks, etc.)
caust1c 1y ago
100% agree. It should be an optional argument for your logging library and handled one time there to be used everywhere.

241 points by JohnScolaro 1y ago

Putting a few important metrics in the logs every 10s is something that the Aerospike datastore also does (https://aerospike.com/docs/database/observe/latency https://aerospike.com/docs/database/observe/latency). This is useful because when you contact support, they run a script to generate a table of historical latencies from the log without depending on you having set up Prometheus, CloudWatch, etc.

dimatura 1y ago

I've found myself adopting this philosophy for a specific use case: monitoring ML training jobs. It's pretty common to see people output training metrics (loss, validation accuracy, etc) every N batches, iterations or epochs. And that does make sense for a lot of reasons, and it's pretty simple to do. But also when you're exploring models that might have wildly varying inference latencies, or using different hardware, or varying batch sizes, or using a differently sized dataset, all of those might end up reporting too infrequently to get an idea of what's happening or too frequently and just spamming too much output. Checkpointing the model every N iterations/epochs/batches has a similar problem - you may end up saving very few checkpoints and risk losing work or waste a lot of time/space with lots of checkpoints. So I've often found myself implementing some kind of monitoring and checkpointing callbacks based on time, e.g., reporting every half an hour, checkpointing every two hours, etc.

AdieuToLogic 1y ago

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.

JohnScolaro 1y ago
Thanks for taking the time to reply! I'm relatively new to working on this type of system (large scale, event driven) and half posted because I know there are people on HN way better than me at this, and was curious about their opinions. In the end, what's the difference between a log and a metric? Is one structured, and one unstructured? Is one a giant blob of text, and the other stored in a time series db? At the moment I guess I'm "logging my metrics" with structured logs going into Loki which can then unwrap and plot things. You and the other commenters have given me the vocabulary to dig more into this area on the internet though. Thanks!
- lelanthran 1y ago
  > In the end, what's the difference between a log and a metric? The goals. The goals of the activity is the difference. The goal of logging is diagnostics and trouble-shooting (when did this break, how often do we see this type of failure, etc). The goal of metrics is to aid in capacity planning (are we close to running out of RAM, do we exceed 80% CPU too often, etc). > You and the other commenters have given me the vocabulary to dig more into this area on the internet though. Read this first; it is a short read (taxonomy of logging, basically): https://www.lelanthran.com/chap10/content.html https://www.lelanthran.com/chap10/content.html
- nixpulvis 1y ago
  I'm not sure I want to weigh in on "log" vs "metric"... but I did want to add some thoughts on logs in general. If you need to "log" something to give users feedback as the system is running, it may be less of a log and more of a progress or status output. Logs to me are things which happen and I want to be able to trace later, so summarizing or otherwise dropping logs that come in quickly in succession would be a problem. If I need to filter I pipe to grep, otherwise I can just save it all and read through it later. Status messaging, which may be informative about your process is useful, and if its goal is to be observed real-time, then yea. A message or two a second seems like a good goal for consistency. These are just two very different use cases to me. And generally I find the former critical to get right, while the later may be nice to have and may lead to discovery by nature of making it more accessible.
- 1y ago
bravesoul2 1y ago
Metrics are way quicker to query due to aggregations and tend to be more stable as features change. It's good to save metrics for things that remain true under arbitrary aggregations. E.g. sum, count, maximum and avoid things that do not survive aggregations such as percentiles.
aflag 1y ago
I thought the post was nice. I've written scripts before where I'd just print by count and be overwhelmed. I should've just used time instead of changing the count number
delusional 1y ago
> This post falls into a common trap; conflating logging with metrics. This isn't as much "conflating" as it is constructing an ad hoc metrics subsystem that exports the metrics to the logs. There's no theoretical difference between exposing a prometheus endpoint that's scraped every x seconds and printing the same data to the logs every x seconds.
jillesvangurp 1y ago
Filter and aggregate after you log your metrics, traces, log messages, etc.; not before. You can worry about data retention, rollups, and other strategies for limiting data storage separately from the systems that emit the data. At least with the right data stores. I kind of like what opensearch and elasticsearch do for this. In Elasticsearch you have a data stream. You configure it to roll over based on time or data size. Once rolled over, indices are read only; new data appends to the current one. You then can define life cycle policies to decide what to do with the old ones and e.g. move them to cold storage, transform them with rollups, and eventually delete them. With application logging, you typically assign different log levels. Trace and debug are typically disabled in production (or should be). Info can be quite noisy. Warn tends to be repetitive (because developers tend to ignore warnings and will never fix them). Errors should be rare. I have my system configured to start emailing me if errors get logged. An error means something is broken and needs to be fixed. Zero tolerance on errors. When an error happens, all the other log information provides me context. So there's value in retaining that. But only for a few days at best. Long enough to survive a weekend or things like Christmas. But after that it's just noise. I have a hard cut at about two weeks. Some places you need to store stuff longer for ass coverage reasons. Data retention comes at a price of course. I've seen companies log ginormous amounts of data and ignoring all their errors. 30GB per day. Absolutely appalling. Me: it looks like your database layer is erroring non stop (constraint violations and worse); you might want to do something about that. Them, ah no that's just normal we just ignore it (php shop, incompetence was the norm). Me: so how do you know when something breaks?! Them: ......?! My well paid consulting gig was beating some sense into this operation as one of the managers noticed they were spending hundreds of thousands per year on this nonsense. My fee was a rounding error on that. Easiest job ever. But kind of cringe worthy once I started looking into what they were actually doing and why. Mostly it's just, "yeah some guy set that up once and then we never looked at it and he left. What are you going to do?!". There was a lot of that with this company. Just absolutely nobody that even cared about the waste of resources or getting any meaningful feedback from their logging. If that's your team, you need to do something about it. That's your job and your not doing it well. If you need an external consultant to tell you, you might want to reflect on the notion of majorly shaking things up a bit.
ejs 1y ago
I built a system for collecting metrics via logs and has worked well for my apps when I don't want to set up a whole separate system for it.
Too 1y ago
One exception to this is batch scripts and other cli tools with a clear start and end, like an installer, rsync, curl, dd, etc. Setting up metrics here is way overkill and the user may still be interested in the progress. Easiest made available through logs. Curses UI could be a nice middle ground but also very often overkill.
jonhohle 1y ago
I enjoyed our metrics systems at Amazon’s and wrote one with a similar API at Okta and should really look at writing another one to open source. One of the huge missing things in metrics systems, imho, is keeping granular metrics in the context of a business operation and then using late aggregation for trends. Last I looked nearly every metrics systems either logged individual events and and required processing for any rollup or aggregated too early and you couldn’t determine the effect on any individual operation/request. There’s a happy medium where you can get per-request counts, stats, and timing and still roll those up at the host/data center/region/granularity to get higher level trends. Most metrics APIs are incompatible with this idea, however.
- Baarsgaard 1y ago
  You're likely talking about "wide events" Which is essentially as many dimensions as possible attached to an event. I believe Meta was the one to develop an internal tool for handling this named Scuba.
kixelated 1y ago
Absolutely. Logs should be bursty, because they're most useful when debugging rare issues. If you have identical log lines, then that should have been a metric instead. Metrics should be sampled based on frequency, because they deduplicate. I'm a huge fan of logarithmically sampling metrics.

perching_aix 1y ago

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

Joker_vD 1y ago
> What then, are you supposed to log the entire application state and every change to it? For replayability/state reconstruction, usually it's enough to log the input data and the decisions made upon them i.e. which branches of the if/switch (and things morally equivalent to them e.g. virtual functions and short-circuiting Boolean operators) you've actually taken. > But then that's way too expensive, Yes, it's usually still way too expensive. But when it's not, it does give you information about at what code point exactly the "wrong" decision was made, and from there you can at least start thinking about how the system could get into the state where it would start making "wrong" decisions at this precise point of code — and that usually cuts down the number of possible reasons tremendously.
cjsawyer 1y ago
My personal answer to this is logging very little during normal operation and then logging a lot during errors. Depending on the maturity of the system “a lot” might mean the entire state so I can debug afterwords.
Veserv 1y ago
Everything is events. The problem is that, as you notice, you frequently encounter situations where there are too many events to handle. Metrics, logging, and tracing are just three different ways to handle that problem. Metrics handles too many events by aggregating them. You handle too many events by squashing them into a smaller number of events that aggregate the information. Logging handles too many events by sampling them. If you have N times as many events as you can handle, take 1 in N of them or whatever other sampling model you want. Tracing is logging, but where you have chains of correlated events. If you have a request started and a request ended event, it is pretty useless to get one without the other. So, you sample at the "chain of correlated events" level. You want 1 in N "chains of correlated events". But, if you have enough throughput for all your events, just get yourself a big pile of events and throw it into a visualizer. Or better yet, just enable time travel debugging tracing so you do not need to even need to figure out how the events map to your program state.

jpgvm 1y ago

If you can can "log by time" then what you need is metrics, not logs.

sethammons 1y ago

Aggregation by time and count together is a normal batching technique and I have used it a lot to scale out multiple parts of many systems. 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.

smohare 1y ago
[dead]

ledauphin 1y ago

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.

kiitos 1y ago
The "compressed form" of logs you're describing here is really just metrics...
- ledauphin 1y ago
  it's not, though. sometimes you need actual active logs to tell you that something is progressing.
  - kiitos 1y ago
    You don't need logs for that, you can get it from metrics just fine. Via absolute value counters, or some kind of percentage-complete gauge, either way you can easily see progress over time...

pjz 1y ago

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.

Thorrez 1y ago
You're talking about a different scenario than than the article. The article is about a strategy of how to generate a single log line. You're talking about a strategy of how to batch multiple log lines together.

haiku2077 1y ago

Best advice I ever got on logging: 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 - https://grugbrain.dev/ https://grugbrain.dev/ 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.

sofixa 1y ago
> log as JSON objects instead of lines of text Or logfmt which is easier to read for humans, lower overhead, and is still structured and supported in at least Grafana/Loki for parsing and queries.
- haiku2077 1y ago
  Does logfmt allow nesting? I often inckude data structures like dicts/maps, arrays or complex objects in my JSON logs.
KronisLV 1y ago
My colleagues love to log as little as possible and most of the projects I’ve seen still treat logs as files instead of event streams that could have some search and filtering and categorization and automated alerting. It’s kind of unfortunate, because for example there’d be pushback against logging branches in code etc., except for trace logs (that others wouldn’t add) that are also off most of the time when problems actually happen. It does help a lot in personal projects though, albeit the limited traffic there kinda minimizes any problems that ample logging might otherwise cause. At least it’s possible to move in the direction of adding some APM like GlitchTip or Skywalking.
- delusional 1y ago
  I've had colleagues try this. It rarely works. Logging every if end up introducing a huge amount of overhead, both in terms of processing power, but especially in terms of storage. You almost always end up having to filter based on some sort of log level that you then turn off by default in production. The problem with that is that you're now required to reproduce the issue after turning on the logging, and if you already have a reproducer, why not just attach a real debugger? The overlap of "we can reproduce" but "it has to run on the production server" ends up being practically zero.

MinimalAction 1y ago

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?

AdieuToLogic 1y ago
> 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? There are different types of logging. What you describe could be defined as an audit log intrinsic to system operation, which is quite a different thing than what the article describes.
- MinimalAction 1y ago
  Oh, I see. My bad then. Could you expand a bit more?
  - AdieuToLogic 1y ago
    >> There are different types of logging. > Oh, I see. My bad then. Could you expand a bit more? Sure, I'll do my best. The terms "logging" and "logs" are overloaded in the software industry and often used assuming context is known. Below are four examples illustrating same. # Program Logs This type of logging is what the article discusses and is what many developers are most familiar with. Usually, each entry is associated with a level (such as "debug", "info", "error", etc.) and capture state relevant to program execution at the point of log emission during the call tree is evaluation. Usually they are used for postmortem analysis when a problem is discovered. # Audit Logs This type of logging serves to record changes in the persistent representation of key abstractions, often due to regulatory requirements. Your example of "a flight data recorder" is a great exemplar. Audit logs for an entity are often independent of other entities and may not support the ability to replay the changes. # Write-Ahead Logs[0] This type of logging is frequently used as an implementation detail for various database technologies, such as RDBMS's. WAL's are most often employed to address database crash recovery and intimately involved with transaction management. # Event Sourcing[1] While Event Sourcing might not be immediately thought of as a form of logging, it becomes clear it is when considering how the events are stored. Most discussions of Event Sourcing either describe it in terms of an Audit Log (like the referenced article does) or as an "append-only log." 0 - https://en.wikipedia.org/wiki/Write-ahead_logging https://en.wikipedia.org/wiki/Write-ahead_logging 1 - https://martinfowler.com/eaaDev/EventSourcing.html https://martinfowler.com/eaaDev/EventSourcing.html

stephenlf 1y ago

Quick and easy.

kqr 1y ago

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.

Bleibeidl 1y ago

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.

sjducb 1y ago

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.

RHSman2 1y ago

Logging (at scale) is the most important thing to understand reality in your system. At scale, realities are many. 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.

RHSman2 1y ago
Btw: logging and the ability to observe systems was the single and most successful act I have done in my career as a Data Product Manager. I have had to fight, do tricks and ‘play the game’ so much. I cannot stress the importance of understanding atomic movements. The cost is high but not as high as the cost of not knowing.

calrain 1y ago

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.

ot 1y ago

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.

layer8 1y ago
That still means each thread will do its own separate log call every second (or whatever the period is) instead of all threads aggregating into a single log call.
- ot 1y ago
  No, the timer is still global (that's why you need the compare-and-swap). But the threads only need to do reads most of the time, and reads do not cause contention. Writes do. It looks something like this (pseudocode): static std::atomic<uint64_t> deadline{0}; auto now = coarse_clock::now(); auto curDeadline = deadline.load(std::memory_order_relaxed); if (now >= curDeadline && deadline.compare_exchange_strong(curDeadline, now + period, std::memory_order_relaxed)) { // Actually log }
  - layer8 1y ago
    Your “actually log” is within one thread. Either the threads all do their separate “actually log”, or they have to synchronize their data into a single shared “actually log”.
    - ot 1y ago
      > Either the threads all do their separate “actually log” But why? Often the purpose is just to log a "been here" signal with some additional details for diagnostics. You don't need to include an accumulation of everything that happened since the last log. All that you care about is that the log happens at most 1/period, say once per second. If you do want to also log some data that accumulates everything that happened, you can accumulate the data in thread-local buffers, and in the "actually log" part collect all the buffers and log them. Since this only happens in the thread that "wins" the CAS, it is still very scalable. This is a very common technique. If you throttle by count, you cannot avoid the contended atomic increment (you can with some sophistication and at the cost of some approximation).

glitchc 1y ago

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.

rco8786 1y ago

it seems like aggregates/metrics are the right tool for this particular thing.

vanschelven 1y ago

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.

stackskipton 1y ago

As SRE/DevOps/Ops whatever, I'm screaming. 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.

aarmenaa 1y ago
I've noticed that for some reason developers really like using logs in place of actual metrics. We use Datadog, and multiple times now I have seen devs add additional logging to an application just so they can then create a monitor that counts those log events. I think it's a path of least resistance thing; emitting logs is very easy, and counting them is also very easy. Reporting actual metrics isn't really difficult either, but unless you're already familiar with the system it's more effort to determine how to do it than just emitting a log line, so yeah.
- chaps 1y ago
  Because when the application is breaking it's good to know why! Logs can be just as ephemeral as metrics -- in many cases, even more so. They're not even mutually exclusive. Where exactly does this anti-logs sentiment come from? Is it because tools like datadog can be lackluster for reading logs across bunches of hosts?

thesuitonym 1y ago

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.

raphting 1y ago

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.

mkl95 1y ago

> Log rate should be consistent 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.

fgonzag 1y ago
Yup, he's trying to solve monitoring and logging with the same setup. I don't think I'd appreciate it, but like all the IT horror stories can be probably made to work.

paffdragon 1y ago

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.

lelandbatey 1y ago

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.

taeric 1y ago

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.

DougN7 1y ago
Except that you waste CPU cycles preparing the log string and calling the log function only to have it all thrown away.
- pvorb 1y ago
  At least in the Java world it is common to let the logging framework handle parameter evaluation for you.
  - jdbernard 1y ago
    This feels like one of those "not obvious until you've seen it in production" requirements: any production-ready logging framework should have a mechanism to delay parameter evaluation until after the threshold/destination checks are performed. Most languages have some version of deferred execution (lazy evaluation, thunks, etc.)

caust1c 1y ago

100% agree. It should be an optional argument for your logging library and handled one time there to be used everywhere.