[erlang-questions] high-volume logging via a gen_server

[Dan Kelley]

On Tue, Oct 5, 2010 at 5:23 AM, Anthony Shipman <als@REDACTED> wrote:

> On Tue, 5 Oct 2010 06:42:17 am Mihai Balea wrote:
> > On Oct 4, 2010, at 2:57 PM, Dan Kelley wrote:
> > > So, what are good strategies to cope with a large incoming volume of
> > > messages that all need to wind up in the same logfile?  Is there a more
> > > efficient way to write to disk than the simple io:format() call than
> I'm
> > > using above?  What's a good way to parallelize the logging over
> multiple
> > > processes but keep all of the information in one file?
> >
>
> You can have a buffer process ahead of the logger. The buffer process just
> has
> to accept and store log requests. A separate write process can pull them
> from
> the buffer (using an async protocol). If the buffer gets too full then you
> can have various policies such as discard oldest, youngest, low priority
> messages etc.


One thing I was surprised to find while profiling yesterday was that much of
the reason that logging was crippling my server was the CPU overhead of
io:format, io_lib:format, and the various calls required to get a high-res
timestamp.  The way my router sets up right now, it takes ~15 microseconds
to parse a reasonably complicated protocol, but about ~100 microseconds to
compose and format the log line which says the parse has happened.

Per what others have suggested in this thread, I had thought that a possible
answer to my bottleneck would be to push as much of the logging work out to
the clients.  That turned out to make per-transaction latency very poor for
the reason described above.

So for now, I've profiled the path which generates the log line strings and
have de-stupided my code a bit to bring the per-log-line latency down to ~60
microseconds.

Taking into account all the responses on the thread (thanks!), and in
conjunction with the formatting changes, I'm trying something like what you
describe:  because it's an easy first step, I'm just replacing writing to
disk directly inside my logging gen_server with calls to disk_log:blog/2.
 So far that's working well.