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

41–50 of 77 posts

Re: Logging can be tricky

#41

Post by jcampbell1 »

evan_miller wrote: post #26
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, r…

I probably read "an otherwise uniform cluster" too literally.

20% utilization on a resource that can only do 100 random operations per second is a major problem, and way different from 5%.

A piece of hardware that operates at 100 Hz, with 20% utilization, will block for about 135ms+ for the 95th percentile request. With 5% utilization, it will block for about 10ms for the 95% percentile request.

My quick calculations are somewhat below the 200ms discrepancy you show in the chart, but not far off.

Of course, turning off fsync is a perfectly good solution. Longer term, I would move to SSDs and just make this entire class of problem go away. I don't even have any spinning platters to test your strace on.

Re: Logging can be tricky

#42

Post by kiyoto »

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.

Logging to files creates a lot of headache. I would say the tail plugin for Fluentd (the open source log collector that I am a maintainer of: www.fluentd.org), I would say 1/3 to 1/2 of the questions are related to tailing log files.

I think, fundamentally, files are the wrong abstraction for log data (as pointed out by Adam Wiggins of Heroku fame: http://12factor.net/logs), but it is something that we are stuck with.

Re: Logging can be tricky

#43

Post by pit »

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.

God bless you -- you are doing the Cloud's work.

Re: Logging can be tricky

#44

Post by unclebucknasty »

evan_miller wrote: post #29
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 on…

Well, yeah, I noticed you guys' response to one of the comments on the blog post indicated that the problem machine had a different workload (additional tasks or something). That caused the additional writes, which then caused the latency for the main app on the box.

I think your point still stands about logging, being cautious about blocking I/O calls, etc. But, it seems the bigger point is one of how your overall system is architected, which proccesses run where, dedicating like nodes to their tasks vs. potential quality/consistency issues arising from having some pull double-duty, etc.

Those seemed to be the source of the real issue here.

Re: Logging can be tricky

#45

Post by idunno246 »

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…

which is why slf4j has format strings

Re: Logging can be tricky

#46

Post by yummyfajitas »

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…

That's not a java problem, that's an "I don't understand Java logging" problem. The right way:

    log.debug("I created this gigantic object {}",
              myBigUglyObject)

Re: Logging can be tricky

#47

Post by evan_miller »

unclebucknasty wrote: post #44
evan_miller wrote: post #29

Earlier quoted context omitted.

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

Well, yeah, I noticed you guys' response to one of the comments on the blog post indicated that the problem machine had a different workload (additional tasks or something). That caused the additional writes, which then caused the latency for the main app on the box. I think your point still stands about logging, being cautious about blocking I/O calls, etc. But, it seems the bigger point is one of how your overall s…

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 example, here I reproduce the problem on a completely isolated machine: https://news.ycombinator.com/item?id=8359556

Re: Logging can be tricky

#48

Post by jamesaguilar »

evan_miller wrote: post #47
unclebucknasty wrote: post #44

Earlier quoted context omitted.

Well, yeah, I noticed you guys' response to one of the comments on the blog post indicated that the problem machine had a different workload (additional tasks or something). That caused the additional writes, which then caused the latency for the main app on the box. I think your point still stands about logging, being cautious about blocking I/O calls, etc. But, it seems the bigger point is one of how your overall s…

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.

Re: Logging can be tricky

#49

Post by tendeer »

While I really like the article and its analysis, I think there is a more general point here - scale is tricky.

Most programming abstractions and tools (such as Logging / UI design / persistence) across instances are all "easy" when it comes to one machine (or a few machines) in a closed, deterministic environment.

All of these become extremely tricky when you have to deal with many instances across many different possibly indeterministic environments. For UI, it quickly becomes what's the viewport? What's the real estate? How is interaction (touch? mouse? keyboard? numpad?). For persistence, one has to worry about number of simultaneous connections, character encoding and normalization, read / writes per second, synchronisation, etc..

So, also for logging - Are we logging client side or over the network? what's the memory on the client? What else is running on the client? What's the permissions through which we log? Do we care about a system call on this client given any user interaction? etc..

Logging, UI, Persistence, Network protocols, heck even just choosing an intermediate data structure are all tricky .. at scale across devices and indeterministic environments.

Re: Logging can be tricky

#50

Post by egwor »

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…

... or your recursive reflective tostring implementation....
Post reply on HN