31–40 of 77 posts
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.
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.
The trouble outlined in my blog post is that the logging framework was calling fsync() -- that is, specifically asking to flush the page cache all the way to disk.
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?
If you record system metrics (eg. to ganglia) then you can also attempt to correlate large pauses to a large and rapidly declining number of dirty bytes in the fs cache.
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.
With fsync() taken out of the equation this is essentially how a naive logger operates. The linux page cache plays the role of shared memory and only under rather heavy contention will a write() incur latency. The trouble outlined in my blog post is that the logging framework was calling fsync() -- that is, specifically asking to flush the page cache all the way to disk.
Earlier quoted context omitted.
Isn't this essentially syslog-ng?
Does syslog-ng use shared memory? I thought it communicated via open socket network channels.
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…
Enclosed log evaluation is really nice and I'd have some trouble going back. It's older than Elixir, too; Commons.Logging in C# has supported it for a long time and most logging frameworks in Scala take a call-by-name parameter rather than an evaluated arg.
https://github.com/playframework/playframework/blob/2.3.x/fr...
The '=>' means call-by-name in Scala, the argument is lazily evaluated.
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…
Earlier quoted context omitted.
With fsync() taken out of the equation this is essentially how a naive logger operates. The linux page cache plays the role of shared memory and only under rather heavy contention will a write() incur latency. The trouble outlined in my blog post is that the logging framework was calling fsync() -- that is, specifically asking to flush the page cache all the way to disk.
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.
In a few cases in the past when dealing with unimportant data I have downgraded to ext2 for a nice performance bump.
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…
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…