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 _______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
