[squid-users] Seeking insight into zeros, negative values in log: 2.6.STABLE18

[Amos Jeffries]

On 6/08/2016 1:03 a.m., Henry S. Thompson wrote:
> Amos wrote:
>> HST wrote:
> ...
>>> Amos wrote:
> ...
>>>> HST wrote:
>>>>>  3) I'm seeing very small numbers (1 in 100000) of negative durations, e.g.
>>>>>
>>>>>     1402744620.389 -70 ... TCP_MISS/200 1882 GET http://... DIRECT/... text/xml
>>>>>     
>>>>>     How should these be understood?
>>>>
>>>> The system clock on your machine went backwards between the request
>>>> arriving and the response being completely sent. Check for issues in
>>>> your NTP setup.
>>>
>>> 1000s of times a day?  Seems . . . unlikely.  But I'll try to get the
>>> sys admin people responsible to investigate.
>>
>> Squid's simply doing a time fetch from the kernel and subtracting
>> Start-time from End-time to get a negative.
>> Note that its on the scale of ~100 milliseconds.
> 
> Sorry but I still don't see how two successive fetchs could result in a
> decrement (w/o an NTP intervention).  

Yes. I could have been clearer by saying the value is likely to be some
few hundred milliseconds off what really happened.

> 
> The negative numbers I'm seeing range up into the low 1000s (of msec,
> right?  That's what the squid documentation says, IIRC).

Yes Squid logs show milliseconds. But...

> 
> Did you really mean "~100 _milliseconds_"?  My understanding was that
> kernel time differences were typically accurate to ~100 _nanoseconds_.
> 

Kernels at nanoseconds. Squid is working in milliseconds. Average
transactions are usually around 100ms and NTP jumps which are probably
behind this are in seconds or milliseconds.

So with NTP jumping around I' give it a rough estimate of the accuracy
being likely to be some 100's of ms different from reality.

> If you can easily tell me where to look in the source, obviously that's
> what I should do....

Sorry. With 2.6 I'm not sure where anything is. 3.x has a lot of change
since then, even 2.7 is significantly different.

In Squid-3 it is src/time.cc getCurrentTime() to fetch when the request
is done parsing, and again when log line is formatted - the value of
current_time stored at those points (not squid_time). With
tvSubMsec(T1(parsed time), T2(logged time)) output used as the duration
column.

So the Squid logs can contain negative duration under exactly four
conditions:
 1) server boot when (and only when) the BIOS clock is innacurate and
jumps around a bit.

 2) daylight savings changes. Only when the server is running in local
timezone clocks instead of proper UTC.

 3) UTC leap seconds/minutes that go backward. (once every six months
that might happen).

 4) NTP service adjusting the kernel clock backwards.

Since you say this is happening noticably often then its #4 and there is
something funky going on with NTP. The others are all at rare and
predictable times.

Amos