Why doesn't SIGVTALRM trigger inside time.sleep()?

Question

I'm trying to use SIGVTALRM to snapshot profile my Python code, but it doesn't seem to be firing inside blocking operations like time.sleep() and socket operations.

Why is that? And is there any way to address that, so I can collect samples while I'm inside blocking operations?

I've also tried using ITIMER_PROF/SIGPROF and ITIMER_REAL/SIGALRM and both seem to produce similar results.

The code I'm testing with follows, and the output is something like:

$ python profiler-test.py
<module>(__main__:1);test_sampling_profiler(__main__:53): 1
<module>(__main__:1);test_sampling_profiler(__main__:53);busyloop(__main__:48): 1509

Note that the timesleep function isn't shown at all.

Test code:

import time
import signal
import collections


class SamplingProfiler(object):
    def __init__(self, interval=0.001, logger=None):
        self.interval = interval
        self.running = False
        self.counter = collections.Counter()

    def _sample(self, signum, frame):
        if not self.running:
            return

        stack = []
        while frame is not None:
            formatted_frame = "%s(%s:%s)" %(
                frame.f_code.co_name,
                frame.f_globals.get('__name__'),
                frame.f_code.co_firstlineno,
            )
            stack.append(formatted_frame)
            frame = frame.f_back

        formatted_stack = ';'.join(reversed(stack))
        self.counter[formatted_stack] += 1
        signal.setitimer(signal.ITIMER_VIRTUAL, self.interval, 0)

    def start(self):
        if self.running:
            return
        signal.signal(signal.SIGVTALRM, self._sample)
        signal.setitimer(signal.ITIMER_VIRTUAL, self.interval, 0)
        self.running = True

    def stop(self):
        if not self.running:
            return
        self.running = False
        signal.signal(signal.SIGVTALRM, signal.SIG_IGN)

    def flush(self):
        res = self.counter
        self.counter = collections.Counter()
        return res

def busyloop():
    start = time.time()
    while time.time() - start < 5:
        pass

def timesleep():
    time.sleep(5)

def test_sampling_profiler():
    p = SamplingProfiler()
    p.start()
    busyloop()
    timesleep()
    p.stop()
    print "\n".join("%s: %s" %x for x in sorted(p.flush().items()))

if __name__ == "__main__":
    test_sampling_profiler()

Answer 1

Not sure about why time.sleep works that way (could it be using SIGALRM for itself to know when to resume?) but Popen.wait does not block signals so worst case you can call out to OS sleep.

Answer 2

Another approach is to use a separate thread to trigger the sampling:

import sys
import threading
import time
import collections


class SamplingProfiler(object):
    def __init__(self, interval=0.001):
        self.interval = interval
        self.running = False
        self.counter = collections.Counter()
        self.thread = threading.Thread(target=self._sample)

    def _sample(self):
        while self.running:
            next_wakeup_time = time.time() + self.interval
            for thread_id, frame in sys._current_frames().items():
                if thread_id == self.thread.ident:
                    continue
                stack = []
                while frame is not None:
                    formatted_frame = "%s(%s:%s)" % (
                        frame.f_code.co_name,
                        frame.f_globals.get('__name__'),
                        frame.f_code.co_firstlineno,
                    )
                    stack.append(formatted_frame)
                    frame = frame.f_back

                formatted_stack = ';'.join(reversed(stack))
                self.counter[formatted_stack] += 1
            sleep_time = next_wakeup_time - time.time()
            if sleep_time > 0:
                time.sleep(sleep_time)

    def start(self):
        if self.running:
            return
        self.running = True
        self.thread.start()

    def stop(self):
        if not self.running:
            return
        self.running = False

    def flush(self):
        res = self.counter
        self.counter = collections.Counter()
        return res

def busyloop():
    start = time.time()
    while time.time() - start < 5:
        pass

def timesleep():
    time.sleep(5)

def test_sampling_profiler():
    p = SamplingProfiler()
    p.start()
    busyloop()
    timesleep()
    p.stop()
    print "\n".join("%s: %s" %x for x in sorted(p.flush().items()))

if __name__ == "__main__":
    test_sampling_profiler()

When doing it this way the result is:

$ python profiler-test.py
<module>(__main__:1);test_sampling_profiler(__main__:62);busyloop(__main__:54): 2875
<module>(__main__:1);test_sampling_profiler(__main__:62);start(__main__:37);start(threading:717);wait(threading:597);wait(threading:309): 1
<module>(__main__:1);test_sampling_profiler(__main__:62);timesleep(__main__:59): 4280

Still not totally fair, but better than no samples at all during sleep.

Answer 3

The absence of SIGVTALRM during a sleep() doesn't surprise me, since ITIMER_VIRTUAL "runs only when the process is executing." (As an aside, CPython on non-Windows platforms implements time.sleep() in terms of select().)

With a plain SIGALRM, however, I expect a signal interruption and indeed I observe one:

<module>(__main__:1);test_sampling_profiler(__main__:62);busyloop(__main__:54): 4914
<module>(__main__:1);test_sampling_profiler(__main__:62);timesleep(__main__:59): 1

I changed the code somewhat, but you get the idea:

class SamplingProfiler(object):

    TimerSigs = {
        signal.ITIMER_PROF    : signal.SIGPROF,
        signal.ITIMER_REAL    : signal.SIGALRM,
        signal.ITIMER_VIRTUAL : signal.SIGVTALRM,
    }

    def __init__(self, interval=0.001, timer = signal.ITIMER_REAL): # CHANGE
        self.interval = interval
        self.running = False
        self.counter = collections.Counter()
        self.timer   = timer                 # CHANGE
        self.signal  = self.TimerSigs[timer] # CHANGE
    ....