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

21–30 of 77 posts

Re: Logging can be tricky

#21

Post by icambron »

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…

Macros let you do option three, too, by just guarding the body with an if in the generated code. That way you avoid having to use an anonymous function each time. So in Lisp (log level (construct-a-string)) instead of (log level (fn [] (construct-a-string))), but with the same elisions logic.

Re: Logging can be tricky

#22

Post by girvo »

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…

Monolog does that, you call the level that you want so you can early-return based on what environment/config you've got set up. Quite nice, means I can keep my debug logs around and deploy the same code to production without worrying about it. I think the PSR standard for logging actually specifies this, too.

Re: Logging can be tricky

#23

Post by mml »

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…

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 line or so... In tight loops, call iter.next in log message and on and on...

Re: Logging can be tricky

#25

Post by lkrubner »

ibar wrote: post #12

I had a similar problem with java -- except that the entire application would freeze for double digit seconds. Another application would sometimes write a huge amount of data out very quickly to the fs cache. 30 seconds later (or w/e the expiration is), all those dirty bytes would get sync'd to disk more or less at once. Turns out it was the JVM provided GC logging hanging on flush (not even fsync) calls. The flush c…

I think I have exactly this problem. How do I confirm this? "strace" does not show me any obvious problems. Where would I look to see if the JVM "flush" was giving me problems?

Re: Logging can be tricky

#26

Post by evan_miller »

jcampbell1 wrote: post #19

If all three machines had the same logging code, and one machine was fsync'ing slowly, isn't turning off fsync just a bandaid that hides the true problem? When they discover the actual problem is some issue with the raid controller, I promise not to say "I told you so".

Hi, post author here. I didn't make it as clear as I could have, but the difference is that the problematic system had an unrelated process creating slightly more writes. I sort-of glossed over this with the 5%-20% difference in i/o util.

Unrelated write activity on a filesystem can cause cause fsync() calls in any other process to vary wildly in latency. This can be replicated, here's an experiment for you. First, run this:

strace -T -efsync ruby -e'loop { STDOUT.fsync; puts "a" * 120; sleep 0.1 } ' > ~/somefile

Then, in another terminal do a little bit of writing -- make sure it is on the same filesystem. For example:

dd if=/dev/zero of=~/someotherfile bs=4M count=1

On my poor little aws VM, here is what I see:

fsync(1) = 0

fsync(1) = 0

fsync(1) = 0

That is, writing 4 megabytes in an unrelated process caused fsync() to jump two orders of magnitude.

Removing fsync() is an appropriate fix because we don't really ever want to flush this data to durable storage.

Re: Logging can be tricky

#27

Post by nkozyra »

Does anyone think about doing logging to shared memory / memcached and then committing snapshots to disk at regular intervals via another process/machine?

If you're not all that concerned about consistency, each web server can keep their logs in a segregated memory space and then another process can combine/commit and send a flush command, leaving the primary machines relatively unencumbered.

Re: Logging can be tricky

#28

Post by spydum »

nkozyra wrote: post #27

Does anyone think about doing logging to shared memory / memcached and then committing snapshots to disk at regular intervals via another process/machine? If you're not all that concerned about consistency, each web server can keep their logs in a segregated memory space and then another process can combine/commit and send a flush command, leaving the primary machines relatively unencumbered.

Isn't this essentially syslog-ng?

Re: Logging can be tricky

#29

Post by evan_miller »

govindkabra31 wrote: post #24

Did anyone understand why logging calls on only problem machine had different fsync behavior than normal machines?

Hi, post author here. The slight difference in i/o (specifically: writes) was the trigger. I talked a little more about that here: http://corner.squareup.com/2014/09/logging-can-be-tricky.htm...

And here: https://news.ycombinator.com/item?id=8359556

Even on the problematic host we only saw this latency issue in the 99th percentile. That is: even on the problem host 99 out of 100 queries were served as expected and only 1 out of 100 saw this additional latency.

Re: Logging can be tricky

#30

Post by nkozyra »

spydum wrote: post #28
nkozyra wrote: post #27

Does anyone think about doing logging to shared memory / memcached and then committing snapshots to disk at regular intervals via another process/machine? If you're not all that concerned about consistency, each web server can keep their logs in a segregated memory space and then another process can combine/commit and send a flush command, leaving the primary machines relatively unencumbered.

Isn't this essentially syslog-ng?

Does syslog-ng use shared memory? I thought it communicated via open socket network channels.
Post reply on HN