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

[Maxim Dounin]

Hello!

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

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

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 Dounin
http://nginx.org/en/donation.html