Log module question: does the buffer mess up the order of the log entries?

Hi experts,

I am reading the log module source code, there is something difficult to
make sure, so I ask for your help.

Access log module use a buffer to buffer log entries before writing to
the file system, the buffer is initialised before the worker processes
are forked, so I guess after the fork(), each worker has a copy, this
also explains why there is no lock-unlock operations while using the
buffer. To be sure about that, I did a simple test:

1, configure nginx to use 16k access log buffer, use the default
keep-alive time(65), work in master-workers mode with a few worker
processes;
2, open one browser, access nginx server, refresh a few times, no access
log generated;
3, open another browser, do the same thing as 2, until the access log
was flushed;

I think there is a chance that the two browser was served by different
worker processes, and log entries may be buffered in different buffers,
which buffer get full first, which will be flush first. According that,
the order of the log entries could be messed up. Unfortunately, I didn’t
see that after testing for a few times.

My question is, Am I wrong about the log module behaviour, or I didn’t
get the right way to test it?

Hello!

On Mon, Sep 23, 2013 at 09:59:29AM +0800, 海峰 刘 wrote:

that, I did a simple test:
different worker processes, and log entries may be buffered in
different buffers, which buffer get full first, which will be
flush first. According that, the order of the log entries could
be messed up. Unfortunately, I didn’t see that after testing for
a few times.

My question is, Am I wrong about the log module behaviour, or I
didn’t get the right way to test it?

Yes, with buffering used log entries may easely be out of order.
(Moreover, even without buffering nothing is guaranteed, even
within a single process - a request made and served later from
client’s point of view, might end up being logged earlier. Mostly
because logging happens once nginx thinks a request is complete,
and this might disagree with client’s point of view.)

To somewhat limit possible log entries misorder with buffering
there is the “flush” argument of the “access_log” directive as
introduced in nginx 1.3.10. It’s not normally needed on loaded
servers as reasonably-sized buffers are filled in seconds, but may
help in case of a varying load.


Maxim D.
http://nginx.org/en/donation.html

On Monday 23 September 2013 05:59:29 海峰 刘 wrote:

see that after testing for a few times.

My question is, Am I wrong about the log module behaviour, or I didn’t get
the right way to test it?

The order of access log entries is undefined anyway if you have more
than
one worker processes.

wbr, Valentin V. Bartenev