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

71–77 of 77 posts

Re: Logging can be tricky

#71

Post by icambron »

heavenlyhash wrote: post #67
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…

> 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. This is a pretty fantastic route as far as syntactical simplicity goes. I wonder if it can have an implications on the generated assembly nonetheless? Could there be extra assembly generated outside the branch for logging level check, which is necessary to bind the v…

You may know this, but maybe it's worth pointing out that the big savings here is actually just that the function itself can be pretty expensive, since it may stringify some data structure. In eagerly evaluated languages, if you say this:

    log("debug", "I found: " + foo.toString());
you end up doing a lot of work to create that string, only to have it be ignored by the log call. Whereas if you say:

    log("debug", => "I found: " + foo.toString());
any extra assembly you execute (or generate) to make that work is peanuts compared to avoiding the call to toString(). None of that (besides the simple thing of log levels) helps with the OP's problem with IO, but it can make a real difference to your CPU.

Re: Logging can be tricky

#73

Post by [deleted] »

Rapzid wrote: post #62
frankzinger wrote: post #56

Earlier quoted context omitted.

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

Disabling buffering in the file library should provide for a similar mitigation outlook. If the OS accepts the writes it WILL make it to disk unless the some part of the storage sub system(or the os itself) fails. So if the process dies recent writes should make it to disk regardless. But if the process triggers a complete system crash then you're kinda stuck needing fsync's :|

[deleted]

Re: Logging can be tricky

#74

Post by frankzinger »

Rapzid wrote: post #62
frankzinger wrote: post #56

Earlier quoted context omitted.

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

Disabling buffering in the file library should provide for a similar mitigation outlook. If the OS accepts the writes it WILL make it to disk unless the some part of the storage sub system(or the os itself) fails. So if the process dies recent writes should make it to disk regardless. But if the process triggers a complete system crash then you're kinda stuck needing fsync's :|

> Disabling buffering in the file library should provide for a similar mitigation outlook

Did you mean logging library? I.e., application-level buffering? In that case, good point.

Re: Logging can be tricky

#75

Post by unclebucknasty »

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…

Good points. I got something out of it on both fronts.

Re: Logging can be tricky

#76

Post by [deleted] »

derefr wrote: post #70
heavenlyhash wrote: post #68

Earlier quoted context omitted.

The OS IPC mechanism quite likely does not use a lock free queue -- or at least, not in quite the same way as I think the grandparent post refers to. Using a well implemented ring buffer [+] can get enqueue operations down to a few instructions and something like two memory fences. The overhead of IPC, which wakes up the kernel scheduler, switches the processor back and forth between privilege modes a few times on th…

I think you're thinking of a synchronous RPC mechanism. I was talking about IPC mechanisms like unix domain sockets, where sending the message doesn't interact at all with the receiving process, but literally just sticks it into a buffer, where the other process can come and get it later.

[deleted]

Re: Logging can be tricky

#77

Post by evan_miller »

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…

Ah, thanks for your feedback. I'm never sure how much detail I should dive into. I will add more next time. I'll answer them here just for practice :)

Recall, this is a problem in the 99th percentile. That is, on average our requests are still taking around 20ms to complete -- but one in every hundred or so takes about 200ms.

The first strace output shows a summary table of time, including both our fast 20ms queries and the 1% of slow 200ms queries. In the summary view I am looking not simply at the largest number in the summary but rather indications that my problematic system is spending time doing something that my healthy system is not. Time spent is a zero-sum equation -- the app is either doing what it's supposed to, or not. futex() is where it should be spending time while idle. fsync() time doubles proportionally, which means it's taking time away from the otherwise productive (or, idle) operations. Which means it's potentially the problem.

When I trace the fsync call individually I see a time delta roughly on par with my per-request delay for the slow 1% of queries. Which indicates to me that this call is happening during the slow queries, accounting for the delay in its entirety.

Post reply on HN