为什么我的Apache访问日志时间戳有时会倒退？

我注意到，在我的Apache日志（实际上是Oracle的品牌HTTP服务器，这实际上是Apache）线的时间戳有时会下降，而不是。这里是一个例子：

1.2.3.4 - - [16/Dec/2014:**13:22:46** +1100] "POST /cas/v1/tickets/TGT-4830717-K5FWqTeJfIajdbae0Zbc1hqSOREWG92fybtLKYtdufKve16Uou-cas-1.2.3.4-2 HTTP/1.1" 200 60 1.2.3.4 - - [16/Dec/2014:**13:12:42** +1100] "POST /self-service/api/account/verification/residential HTTP/1.1" 400 0 1.2.3.4 - - [16/Dec/2014:13:12:15 +1100] "GET /self-service/api/accounts/38909 HTTP/1.1" 404 0 1.2.3.4 - - [16/Dec/2014:13:20:46 +1100] "GET /self-service/oamCallback?authn_try_count=1&contextType=external&username=string&contextValue=%2Foam&password=sercure_string&challenge_url=https%3A%2F%2Fwww.xxx.com.au%2Fmyaccount%2FoamCallback&request_id=-3108004070152329208&p_error_code=OAM-2&p_error_codes_list=OAM-2&locale=en_US&resource_url=https%253A%252F%252Fwww.xxx.com.au%252Fmyaccount%252Fapi%252Fprofile HTTP/1.1" 401 70 1.2.3.4 - - [16/Dec/2014:13:22:46 +1100] "GET /cas/proxyValidate?&ticket=ST-4830713-csoZibAECToKVXXYTIVS-cas-1.2.3.4-2&service=http%3A%2F%2F1.2.3.4%3A7002%2Fservlet%2FREST%2Fsites%2FxxxQuotes%2Ftypes%2FPage%2Fassets%2F1343354161974 HTTP/1.1" 200 704

看看第二行比第一行快了10分钟吗？

这是正常的吗？

或者，如果没有，任何想法是什么原因呢？

日志消息中的时间指示接收请求的时间。但是每个请求只有在处理完成后才被logging。

这意味着如果某些请求需要很长时间才能处理，则可能会出现乱序。我发现在LogFormat包含%D是很有用的，这样我可以看到每个请求需要多less微秒。

如果你的日志里有这个，你就会知道第二个请求是否需要处理10分钟。

不，从单调增长的意义上讲，这不是“正常的”。

但有时甚至可能发生，即使系统中没有任何错误：

13:22，系统date改回13:12，也许是因为你的ntp同步恶魔
有多个Apache进程，他们正在写入相同的日志文件。如果第一个进程收到请求，但是它被超时了，那么它的入口只有在超时之后才能写入日志。在其他儿童进程中可以正常工作。

如果偏差是圆的（例如，正好10分钟），那么（2）更有可能，因为系统时钟的每日延迟不会太多。

如果它经常发生（更常见的是你的时钟同步守护进程设置时钟），这也是（2）的投票。

但是在（1）的情况下，时钟同步工具（可能是你系统上的ntp）肯定会logging下来。挖掘日志find，如果它发生。