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?

[Maxim Dounin]

Hello!

Post by 海峰 刘
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
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?

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.

[Valentin V. Bartenev]

Post by 海峰 刘
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
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?

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

wbr, Valentin V. Bartenev