Hacker News Board Hacker News, browsed like a classic message board
Live data from Hacker News

Log by time, not by count

johnscolaro.xyz

Post reply on HN
Print view View original

61–70 of 109 posts

Re: Log by time, not by count

#61

Post by layer8 »

ot wrote: post #59
layer8 wrote: post #54

Earlier quoted context omitted.

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.

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 deadline{0}; auto now = coarse_clock::now(); auto curDeadline = deadline.load(std::memory_order_relaxed); if (now >= curDeadline && deadline.compare_exchange_strong(curDeadline, now…

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

Re: Log by time, not by count

#62

Post by thesuitonym »

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.

Re: Log by time, not by count

#63

Post by raphting »

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.

Re: Log by time, not by count

#64

Post by bunderbunder »

jiehong wrote: post #55
haiku2077 wrote: post #20

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/ The only one I'll add is…

Following this advice, I've seen service where you could say the main function was to produce logs, and the actual response to the user was only a small part of the traffic generated. What we really need is smart logging: only log the full span when an error is detected, otherwise no need for it. But it's not a very well supported case.

I worked at a place that banned logging levels. Everything sent to to the "log" function gets written to the logs, period. And then the rest was left to the services' maintainers to figure out.

That, combined with a real, genuine devops scheme where the people implementing the system and the people keeping it running in production where on the same team and generally the same actual people, seemed to produce some of the most excellent and usable logging I've ever seen. Without needing a whole bunch of rules to try and force everyone to (still fail to) get there.

One neat thing that I think really facilitated this was the sense of empowerment that came with having exactly one rule (logging isn't configurable) combined with one goal (keep the system up). We did decide we wanted smart logging along those lines. And we did see that existing solutions didn't support this very well. So someone wrote one. And it was so dead simple, and easy to use. The 'user manual' for new hires was basically, "Here's 50 lines of code that you should read."

Re: Log by time, not by count

#65

Post by KronisLV »

delusional wrote: post #43
KronisLV wrote: post #31

Earlier quoted context omitted.

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 problem…

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 al…

> why not just attach a real debugger?

Probably due to no direct access to the environments, whereas there being less organizational resistance to toggling logging levels... assuming that the issue is even easily reproducible instead of "Okay, this happened once and cost us X$, it was pretty horrible, we don't know exactly why that happened but fix it before it happens again."

(not an exact case, but a pattern I've seen)

Re: Log by time, not by count

#66

Post by mkl95 »

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

Re: Log by time, not by count

#67

Post by aarmenaa »

stackskipton wrote: post #58

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 al…

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.

Re: Log by time, not by count

#68

Post by lillecarl »

danpalmer wrote: post #28
AdieuToLogic wrote: post #18

Earlier quoted context omitted.

> In the end, what's the difference between a log and a metric? Essentially, a log entry is the emission of state known by an individual code execution path at the point the log entry can be produced, whereas a metric is a measurement of a specific runtime execution performed by the system. For example, a log entry of: module_logger.info( f"Processed {num_events_processed_since_last_log} events." ) Emits a log entry…

This is a reasonable first pass answer, but there's more nuance to this... > What it does not do is separate this information Logging at scale should really be structured, which means that you can trivially differentiate between different types of log message. You also get more dimensions all represented in that structure. > limits the type of metrics which can be reported to be those expressible in a message text fi…

I think what you're saying is that you can make a logging system LARP metrics. At the end it's logging on fd 1 and 2 and metrics are usually over http, but ofc you can dump "metrics" into stout, it's not as practical with what tools are built for what.

In my local fun projects that run on my machine I might dump metrics into the logs because it's practical, but it doesn't make it "right".

Re: Log by time, not by count

#69

Post by ot »

layer8 wrote: post #61
ot wrote: post #59

Earlier quoted context omitted.

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 deadline{0}; auto now = coarse_clock::now(); auto curDeadline = deadline.load(std::memory_order_relaxed); if (now >= curDeadline && deadline.compare_exchange_strong(curDeadline, now…

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

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

Re: Log by time, not by count

#70

Post by paffdragon »

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.
Post reply on HN