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

[Henry S. Thompson]

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).  

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

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

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

ht
-- 
       Henry S. Thompson, School of Informatics, University of Edinburgh
      10 Crichton Street, Edinburgh EH8 9AB, SCOTLAND -- (44) 131 650-4440
                Fax: (44) 131 650-4587, e-mail: ht at inf.ed.ac.uk
                       URL: http://www.ltg.ed.ac.uk/~ht/
 [mail from me _always_ has a .sig like this -- mail without it is forged spam]