Unexpected tornado.ioloop.PeriodicCallback behavior

Question

Trying to figure out how PeriodicCallbacks got scheduled, I wrote this script:

import time
import tornado.ioloop

t0 = time.time()

def foo():
    time.sleep(1)
    print(time.time() - t0)

tornado.ioloop.PeriodicCallback(foo, 2000).start()
tornado.ioloop.IOLoop.instance().start()

I expected it to fire either every 2 or every 3 seconds, depending on whether tornado waited until completion to schedule the next event. However, I got this:

3.00190114975
6.00296115875
10.0029530525
14.0029621124
18.0029540062
22.0050959587
26.0040180683
30.005161047
34.0053040981

What's going on here?

Answer 1

Sleeping, even in a "background" PeriodicCallback, is never a good idea in a tornado app because it blocks the IOLoop and can prevent it from scheduling things appropriately. If you're using Tornado, you need to replace all long blocking calls with non-blocking equivalents (or move them to other threads). Replace sleeps with IOLoop.add_timeout, networking operations with IOStream or other asynchonous libraries, etc.

Answer 2

I think you're just seeing a delay caused by the overhead of running the IOLoop. For example, if I change the PeriodicCallback to run every 5 seconds, I get this output:

6.00595116615
12.0075321198
17.0060141087
22.0051832199
27.0067241192
32.0061450005
37.0066981316
42.0063281059
47.0067460537

Which is pretty much exactly what you'd expect. Also, to answer your original question, PeriodicCallback schedules the next run of the callback after doing the sleep (this is taken directly from the Tornado source code):

class PeriodicCallback(object):
    def __init__(self, callback, callback_time, io_loop=None):
        self.callback = callback
        if callback_time <= 0:
            raise ValueError("Periodic callback must have a positive callback_time")
        self.callback_time = callback_time
        self.io_loop = io_loop or IOLoop.current()
        self._running = False
        self._timeout = None

    def start(self):
        """Starts the timer."""
        self._running = True
        self._next_timeout = self.io_loop.time()
        self._schedule_next()

    def _run(self):
        if not self._running:
            return
        try:
            self.callback() # Your function runs here.
        except Exception:
            app_log.error("Error in periodic callback", exc_info=True)
        self._schedule_next()  # Schedule next run after calling self.callback

    def _schedule_next(self):
        if self._running:
            current_time = self.io_loop.time()
            while self._next_timeout <= current_time:
                self._next_timeout += self.callback_time / 1000.0
            self._timeout = self.io_loop.add_timeout(self._next_timeout, self._run) # The callback is actually scheduled with the ioloop here.