[Twisted-Python] LoopingCall.withCount countCallable called with 0

[Glyph Lefkowitz]

> On Mar 24, 2015, at 2:49 AM, Dario Vinella <d.vinella at gmail.com> wrote:
> 
> Hi all,
> 
> I found an odd behavior using a LoopingCall.withCount with a very small interval (0.02 sec): sometimes the countCallable is called with 0 as argument and it looks like the now - _realLastTime is smaller than the looping interval.

So, this can definitely happen if time goes backwards, but it has to go backwards between the time that the reactor starts executing timed calls and the time that LoopingCall looks at the timestamp to compute what the value passed to withCount should be.  If it were smaller than the LoopingCall's time-to-run 

> Here you can find the very simple code I use to reproduce the "anomaly", with a main loopingCall and another one that prints its internals
> 
> https://gist.github.com/dvinella/31d94f9dd0e47586658d <https://gist.github.com/dvinella/31d94f9dd0e47586658d>

An even more straightforward way to figure out if it's a problem with your machine would be this:

import time
from itertools import count

then = time.time()
for ever in count():
    now = time.time()
    print("{},{}".format(ever, (now - then) * 10e6))
    then = now

It would be good to look at how many of these numbers are negative.

> and here an extract of the logs it produces
> 
> https://gist.github.com/dvinella/8cfdce0b9f5fdda7b375 <https://gist.github.com/dvinella/8cfdce0b9f5fdda7b375>
> 
> The doc for the withCount states that the argument should be normally 1, higher if the reactor blocks for some reason, but it doesn't say anything about 0.
> The beahavior is quite misleading since the loop seems to anticipate the interval timeout, saying "I've been called, but I should have not been called"

That seems right.  I think there's a real problem here, since physical clocks do just fail, and sometimes NTP slew has to happen.  LoopingCall.withCount has a clear opportunity to notice that time has gone backwards, and can just skip that call.  This is assuming that time has gone backwards by a tiny amount for a brief period of time, though, and does not address the more complex issue of "the clock was set some significant distance into the past".  LoopingCall still isn't going to be able to deal with large amounts of clock drift, we'd need a monotonic version for that :).

> I must add that the anomaly doesn't appear right at the start, but after tens of seconds, mostly when the system is under medium/heavy load.

Even seriously broken clocks don't go backwards a lot. ;-)

> So is it only a documentation issue for an exceptional case, due to timers imprecision, that should be handled at higher levels, or is it a real issue?

I think it's a real issue.

The point of withCount is supposed to be that it keeps track of how far into a sequence you should advance, for example, into the frames of an animation.  If your callback advances by N frames each time it's called, it's supposed to be up-to-date with "real time".

Assuming that the reason time is going backwards is that your ntp daemon is correcting your clock, every time withCount's callback gets called with 0, _realLastTime gets updated, which means that the "frame" we should have advanced is simply lost, and it will slowly fall behind real time each time this happens.

So while the calls with 0 themselves are a minor annoyance, they are a symptom of a problem that makes it impossible for LoopingCall to do its job properly in some cases, and should definitely be fixed.

Thanks for reporting!  Can you open a ticket?

-glyph
-------------- next part --------------
An HTML attachment was scrubbed...
URL: </pipermail/twisted-python/attachments/20150324/b19af633/attachment-0002.html>