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

61–70 of 77 posts

Re: Logging can be tricky

#61

Post by evan_miller »

jacques_chester wrote: post #59
evan_miller wrote: post #38

Earlier quoted context omitted.

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.

Yes. I haven't done anything with a log-structured FS. I have only played around with conventional filesystems.

Re: Logging can be tricky

#62

Post by Rapzid »

frankzinger wrote: post #56
TheLoneWolfling wrote: post #18

Earlier quoted context omitted.

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)?

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 :|

Re: Logging can be tricky

#63

Post by rjbwork »

oftenwrong wrote: post #60
rjbwork wrote: post #31

Earlier quoted context omitted.

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?

We used Azure SQL for our RDBMS requirements, and blob/table storage for our NoSQL stuff. Sure there's a server behind it, but it's transparent to us and it's geo-redundant and replicated. When i say "no servers" what I mean is, we don't need any system admins and very little ops folks. In fact at the moment, devs are pretty much ops since we need very little of it.

I also forgot to mention we have a build server, but thats just a virtual machine that we backup regularly. It's our only piece of static infrastructure. Everything else, except storage which is, again, transparent to us, is destroyed on a weekly, if not daily, basis for new releases.

Re: Logging can be tricky

#64

Post by hoov »

derefr wrote: post #17
dclusin wrote: post #3

Compressing the text logs prior to writing them to the disk also helps with these kinds of issues. You can also offload your logging to a dedicated thread and then use a lock free queue to increase your performance even more.

> You can also offload your logging to a dedicated thread and then use a lock free queue to increase your performance even more. Or use syslog() like a sane person, and let that "extra thread" live inside the OS IPC mechanism. (Or stdout/stderr like a modern sane person, and let upstart/systemd/docker/etc. push your logs to syslog if that's where it feels like pushing them.)

> Or use syslog() like a sane person, and let that "extra thread" live inside the OS IPC mechanism.

As it turns out, we had nearly the same symptoms as the OP. After running strace on syslogd (CentOS 5), I realized that it also does an fsync() after every call. A quick trip to the man page and a configuration change later, our issues disappeared.

Re: Logging can be tricky

#65

Post by snuxoll »

shabble wrote: post #55
jamesaguilar wrote: post #48

Earlier quoted context omitted.

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.

Which is why logging to disk on the server is BAD, have your log framework write to stdout and have upstart/systemd/whatever handle writing to a remote syslog server or whatever your fancy is.

Re: Logging can be tricky

#67

Post by heavenlyhash »

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.

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 variables for the closure?

Similarly, I might suspect that an optimizing compiler that is considering a function for inlining might change its mind for any function where it sees a nontrivial closure like that, without knowing that "trace" level logging nearly never happens.

"Edge cases", to be sure, and the answers are surely different between languages, but interesting to consider nonetheless.

Re: Logging can be tricky

#68

Post by heavenlyhash »

derefr wrote: post #17
dclusin wrote: post #3

Compressing the text logs prior to writing them to the disk also helps with these kinds of issues. You can also offload your logging to a dedicated thread and then use a lock free queue to increase your performance even more.

> You can also offload your logging to a dedicated thread and then use a lock free queue to increase your performance even more. Or use syslog() like a sane person, and let that "extra thread" live inside the OS IPC mechanism. (Or stdout/stderr like a modern sane person, and let upstart/systemd/docker/etc. push your logs to syslog if that's where it feels like pushing them.)

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 the way, knocks apart all the CPU cache and register state to swap in another process, while the MMU is flipping all your pages around because these two processes don't trust each other to write directly into their respective memory... is not going to have quite the same performance characteristics.

An moment in the history of logging is java's log4j framework, which, within a single process, used exclusive synchronization. When this was replaced by a (relatively) lock-free queue implementation, throughput increased by orders of magnitude. (Their notes and graphs on this can be found at https://logging.apache.org/log4j/2.x/manual/async.html .) This isn't an exact metaphor for the difference between a good lockfree ringbuffer and IPC either, but it certainly has some similarities, and indeed ends with a specific shout-out to the power of avoiding "locks requiring kernel arbitration".

--

[+] The "mechanical sympathy" / Disruptor folks have some great and accessible writeups on how they addressed the finer points of high performance shared memory message passing. http://mechanitis.blogspot.com/2011/06/dissecting-disruptor-... is one of my favorite reads.

Re: Logging can be tricky

#69

Post by derefr »

aidos wrote: post #53
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…

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?

Everything goes through an async message send to a gen_event (error_logger). The gen_event itself can have annoyingly synchronous+serial behavior with respect to its backends, but gen_event handlers aren't supposed to do much heavy-lifting; they mostly just decide whether they want a message, and then forward it to some backend process to do the formatting+writing+etc.

This gives you another neat benefit, nearly for free: if you have, say, application Foo on node A, wanting to log to SyslogSink on node B, then Foo first sends its logs to a gen_event on A, and the SyslogSink handler in that gen_event gets the opportunity to drop messages, using whatever logic SyslogSink likes, before forwarding them over to B (which might be half-way across the Internet.)

Re: Logging can be tricky

#70

Post by derefr »

heavenlyhash wrote: post #68
derefr wrote: post #17

Earlier quoted context omitted.

> You can also offload your logging to a dedicated thread and then use a lock free queue to increase your performance even more. Or use syslog() like a sane person, and let that "extra thread" live inside the OS IPC mechanism. (Or stdout/stderr like a modern sane person, and let upstart/systemd/docker/etc. push your logs to syslog if that's where it feels like pushing them.)

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.
Post reply on HN