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

Logging can be tricky

corner.squareup.com

Post reply on HN
Print view View original

51–60 of 77 posts

Re: Logging can be tricky

#51

Post by arethuza »

mml wrote: post #23
derefr wrote: post #16

Earlier quoted context omitted.

Thus why your logging library should have a configurable log-level, and the first thing the user-facing log() function should do is check the arguments against the log-level and early-return if the message isn't important enough. (In languages that support macros, you could also just make debug_log() a macro that gets compiled out on release builds, like assert(). That means a whole bunch of object files are going to…

At least in Java, log levels don't buy you much when you wind up possibly rendering object graphs to strings (via your ohsohelpful custom, recursive tostring implementation), then duping it to concat "made it here" to it, then immediately abandon the mess on the heap for the gc to handle, since the production log level is warn, so your carefully built, highly detailed log message is never used. Repeat every other lin…

"possibly rendering object graphs to strings"

But that's a problem with how you choose to use logging in your application - not with logging in general or specific logging features in Java.

Logging used without any care can cause lots of problems - but then so can any part of an application. Used with some care it can be a very useful tool for helping to diagnose all kinds of problems.

Re: Logging can be tricky

#52

Post by erikb »

Evan, I would be happy if you could explain more about what you see in the strace outputs. E.g.:

> Time spent in fsync accounts for almost exactly the delay we were seeing.

What delay? I see the whole thing taking 1.5 seconds and 1.3 seconds spent in futex (0.4 more than on the normal host). Not sure, why we are suddenly talking about fsync. I also don't know what either method (futex, fsync) could be doing.

All these are not questions I want answers to (some stuff I could google of course). I just want to show that it's a rather confusing read for some readers if you expect them to understand the strace outputs as well as you do, when you seem to be using that tool on a daily basis and the readers might not have used it at all, ever. It would be great to follow your insides better. Just small additions like the following would help a lot: "[The X seconds] spent in fsync [seen in diagram A] accounts for almost exactly the delay we were seeing [in diagram B]".

Re: Logging can be tricky

#53

Post by aidos »

derefr wrote: post #16
mml wrote: post #10

Reminds me of the time I sped up the main business app of a large company by 85% by removing "debug" logging. 2tb/hr of "made it here" isn't really useful at the end of the day. Not the first time I've seen that by a long shot. //shakes zimmerframe, shuffles off

Thus why your logging library should have a configurable log-level, and the first thing the user-facing log() function should do is check the arguments against the log-level and early-return if the message isn't important enough. (In languages that support macros, you could also just make debug_log() a macro that gets compiled out on release builds, like assert(). That means a whole bunch of object files are going to…

Clever. I like that (using the closure).

I've never used Elixir but toyed with Erlang many years ago - is it called asynchronously by the logging process in Elixir? If so, I guess you're relying on immutable data structures to make sure you get the correct logging output?

Re: Logging can be tricky

#54

Post by masklinn »

derefr wrote: post #16
mml wrote: post #10

Reminds me of the time I sped up the main business app of a large company by 85% by removing "debug" logging. 2tb/hr of "made it here" isn't really useful at the end of the day. Not the first time I've seen that by a long shot. //shakes zimmerframe, shuffles off

Thus why your logging library should have a configurable log-level, and the first thing the user-facing log() function should do is check the arguments against the log-level and early-return if the message isn't important enough. (In languages that support macros, you could also just make debug_log() a macro that gets compiled out on release builds, like assert(). That means a whole bunch of object files are going to…

> My favourite solution by far, though, is the one recently implemented by Elixir: log() is a regular function, but takes a closure instead of a string.

A pretty common halfway solution (used by Python's logging for instance) is that the logging library takes a format string and its parameters, and does the formatting itself.

Doesn't save intermediate lookups or complex computations if they exist, but for the common case of a complex stringification it can save your bacon.

The alternative is an explicit conditional around the logging call, which is definitely worse than the ability to log a closure.

Re: Logging can be tricky

#55

Post by shabble »

jamesaguilar wrote: post #48
evan_miller wrote: post #47

Earlier quoted context omitted.

Sort of. The catch is that even a very small write, say just a few megabytes, can drastically change the cost of an fsync(). On my test aws VM even writing just 4 megabytes one time is enough to trigger the problem. Even on an otherwise fully isolated system a few megs may be written from time to time, for example by a management agent like chef or puppet. Or by an application deploy copying out new binaries. For exa…

IMO the real issue is that a competent logging framework doesn't block app code to sync the log to disk. The buffer should be swapped out under lock, and then synced in a separate thread. Yuck.

The downside is of course that if you crash hard, the most valuable log entries are the ones least likely to be on-disk afterwards.

Re: Logging can be tricky

#56

Post by frankzinger »

TheLoneWolfling wrote: post #18
sargun wrote: post #9

Why would you fsync logs for a high-level service? Are you afraid a power outage is going to cause you to lose service logs?

Making sure your logging data gets written is relatively important. Say, if you hit a bug somewhere that causes the server itself to crash.

How about installing a SIGSEGV, etc. handler to do the fsync (and perhaps even print a stacktrace)?

Re: Logging can be tricky

#57

Post by allegory »

mml wrote: post #10

Reminds me of the time I sped up the main business app of a large company by 85% by removing "debug" logging. 2tb/hr of "made it here" isn't really useful at the end of the day. Not the first time I've seen that by a long shot. //shakes zimmerframe, shuffles off

Not the only one. Someone set up NHibernate on a project I was working on to run logging in DEBUG mode and throw it in a log file capped at 100k. Pages were taking 4-5 seconds to render. Wasn't obvious that the logs were being written as the file was capped at 100k.

Took ages to work that out.

Ugh.

Re: Logging can be tricky

#58

Post by zorbo »

erikb wrote: post #52

Evan, I would be happy if you could explain more about what you see in the strace outputs. E.g.: > Time spent in fsync accounts for almost exactly the delay we were seeing. What delay? I see the whole thing taking 1.5 seconds and 1.3 seconds spent in futex (0.4 more than on the normal host). Not sure, why we are suddenly talking about fsync. I also don't know what either method (futex, fsync) could be doing. All thes…

> Just small additions like the following would help a lot: "[The X seconds] spent in fsync [seen in diagram A] accounts for almost exactly the delay we were seeing [in diagram B]".

Exactly. I try to always point to the actual data when I'm telling my readers my conclusions.

"Calls to futex, epoll_wait and select are largely the same on both systems. The problem host does 1727 calls to fsync(), while the normal host does only 849 calls. The problem host spends 1.24% of its time in fsync(). The normal host only 0.48%. This makes fsync() our number 1 suspect."

This at least lets the reader refer back to the output and see corresponding entries.

Re: Logging can be tricky

#59

Post by jacques_chester »

evan_miller wrote: post #38
jacques_chester wrote: post #34

Earlier quoted context omitted.

Have you experimented with a log-structured filesystem? I once saw similar high-variation behaviour in a logging problem on extfs. Switching to NILFS pretty much got rid of variable latency entirely.

Not recently, no. I do know that a journaled filesystem can exacerbate this sort of problem as it can make extra work. For example: http://lwn.net/Articles/328363/ In a few cases in the past when dealing with unimportant data I have downgraded to ext2 for a nice performance bump.

Just to make sure we're talking about the same thing, a journalling FS isn't the same thing as a log-structured FS.

The first has a write-ahead log, the latter is basically just a log. So immediately writing to disk is relatively simple.

Re: Logging can be tricky

#60

Post by oftenwrong »

rjbwork wrote: post #31
canterburry wrote: post #11

Wow...this post made me think I shouldn't even attempt to run my own server infrastructure for my startup. This kind of analysis is way deeper than I'm currently capable of.

Hell, we're now infrastructure-less. No VM's (except for our QA to test on, doesn't count), no static servers we can't just destroy and spin up another of in It truly is a joy.

Curious: How do you persist data with no database servers? Using an outside service to store it?
Post reply on HN