Debugging gevent hangs with manhole

0_gevent_debug.rst

Debugging gevent hangs with manhole

If you have a hung process, find its PID and skip this. Otherwise, let's create a dummy hang:

$ cd teuthology
$ curl -O https://gist.githubusercontent.com/zmc/55b697822f332cadf297dfb98b2dcecd/raw/46efb4276f3e98224ae725e8f27c4fb2047c35f8/gevent_debug.py
$ source ./virtualenv/bin/activate
$ python
>>> import os; print os.getpid()
8675309
>>> from teuthology.orchestra import remote
>>> r = remote.Remote('mira121')
>>> r.run(args='sleep 300')

In another terminal, let's debug the hang:

$ kill -USR1 8675309
$ nc -U /tmp/manhole-8675309
$ import gevent_debug
$ gevent_debug.main('/tmp/gevent_traces.txt')

The last line above will cause traces to be dumped to the terminal, but also logged to the file. This gist contains some sample output.

Look through the traces, skipping ones that mention manhole, try to locate the blocking call. Initially, also skip traces whose outermost frame is anything in .../site-packages/gevent/. Ignoring those, we see:

Greenlet <greenlet.greenlet object at 0x10787c550>
Stack:
File "<stdin>", line 1, in <module>
File "teuthology/orchestra/remote.py", line 193, in run
  r = self._runner(client=self.ssh, name=self.shortname, **kwargs)
File "teuthology/orchestra/run.py", line 423, in run
  r.wait()
File "teuthology/orchestra/run.py", line 143, in wait
  greenlet.get()
File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/greenlet.py", line 465, in get
  result = self.parent.switch()
File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/hub.py", line 630, in switch
  return RawGreenlet.switch(self)

There's what's blocking the process - our call to Remote.run() from the interpreter.

In this example, debugging was easy. In more complex situations, it can still take a decent amount of work to find the culprit.

gevent_debug.py

import gc
import gevent
import traceback


def find_greenlets():
    greenlets = list()
    objects = gc.get_objects()
    for obj in objects:
        if isinstance(obj, gevent.greenlet.greenlet):
            greenlets.append(obj)
    return greenlets


def greenlet_stack(obj):
    return ''.join(traceback.format_stack(obj.gr_frame))


def main(path=None):
    log_file = None
    if path is not None:
        log_file = open(path, 'w')
    greenlets = find_greenlets()
    for greenlet in greenlets:
        msg = "Greenlet %s" % greenlet
        print msg
        if log_file:
            log_file.write(msg + '\n')
        try:
            msg = "Stack:\n%s" % greenlet_stack(greenlet)
            if log_file:
                log_file.write(msg + '\n')
            print msg
        except Exception:
            traceback.print_exc()
            if log_file:
                log_file.write(traceback.format_exc() + '\n')
        print

gevent_traces.txt

Greenlet <Greenlet at 0x109d93870>
Stack:
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/hub.py", line 688, in run
    loop.run()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/manhole.py", line 468, in handle_oneshot
    ManholeConnectionThread.handle(client, self.thread.locals)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/manhole.py", line 268, in handle
    run_repl(locals)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/manhole.py", line 323, in run_repl
    ManholeConsole(namespace).interact()
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/code.py", line 243, in interact
    more = self.push(line)
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/code.py", line 265, in push
    more = self.runsource(source, self.filename)
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/code.py", line 87, in runsource
    self.runcode(code)
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/code.py", line 103, in runcode
    exec code in self.locals
  File "<console>", line 1, in <module>
  File "gevent_debug.py", line 31, in main
    msg = "Stack:\n%s" % greenlet_stack(greenlet)
  File "gevent_debug.py", line 17, in greenlet_stack
    return ''.join(traceback.format_stack(obj.gr_frame))

Greenlet <Greenlet at 0x109d93af0: copy_file_to(<paramiko.ChannelFile from <paramiko.Channel 1 (EO, <logging.Logger object at 0x10a06e890>, None)>
Stack:
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/greenlet.py", line 536, in run
    result = self._run(*self.args, **self.kwargs)
  File "teuthology/orchestra/run.py", line 294, in copy_file_to
    copy_to_log(src, logger)
  File "teuthology/orchestra/run.py", line 261, in copy_to_log
    for line in f:
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/file.py", line 102, in next
    line = self.readline()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/file.py", line 277, in readline
    new_data = self._read(n)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/channel.py", line 1305, in _read
    return self.channel.recv_stderr(size)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/channel.py", line 713, in recv_stderr
    out = self.in_stderr_buffer.read(nbytes, self.timeout)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/buffered_pipe.py", line 156, in read
    self._cv.wait(timeout)
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/hub.py", line 630, in switch
    return RawGreenlet.switch(self)

Greenlet <Greenlet at 0x109d93690: copy_file_to(<paramiko.ChannelFile from <paramiko.Channel 1 (EO, <logging.Logger object at 0x10a06e9d0>, None)>
Stack:
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/greenlet.py", line 536, in run
    result = self._run(*self.args, **self.kwargs)
  File "teuthology/orchestra/run.py", line 294, in copy_file_to
    copy_to_log(src, logger)
  File "teuthology/orchestra/run.py", line 261, in copy_to_log
    for line in f:
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/file.py", line 102, in next
    line = self.readline()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/file.py", line 277, in readline
    new_data = self._read(n)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/channel.py", line 1293, in _read
    return self.channel.recv(size)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/channel.py", line 665, in recv
    out = self.in_buffer.read(nbytes, self.timeout)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/buffered_pipe.py", line 156, in read
    self._cv.wait(timeout)
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 340, in wait
    waiter.acquire()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/hub.py", line 630, in switch
    return RawGreenlet.switch(self)

Greenlet <Greenlet at 0x109d939b0: <bound method Transport.__bootstrap of <paramiko.Transport at 0xa03e190L (cipher aes128-ctr, 128 bits) (active; 1 open channel(s))>>>
Stack:
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/greenlet.py", line 536, in run
    result = self._run(*self.args, **self.kwargs)
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 774, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/transport.py", line 1765, in run
    ptype, m = self.packetizer.read_message()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/packet.py", line 391, in read_message
    header = self.read_all(self.__block_size_in, check_rekey=True)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/paramiko/packet.py", line 254, in read_all
    x = self.__socket.recv(n)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/_socket2.py", line 283, in recv
    self._wait(self._read_event)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/_socket2.py", line 182, in _wait
    self.hub.wait(watcher)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/hub.py", line 651, in wait
    result = waiter.get()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/hub.py", line 899, in get
    return self.hub.switch()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/hub.py", line 630, in switch
    return RawGreenlet.switch(self)

Greenlet <greenlet.greenlet object at 0x10787c550>
Stack:
  File "<stdin>", line 1, in <module>
  File "teuthology/orchestra/remote.py", line 193, in run
    r = self._runner(client=self.ssh, name=self.shortname, **kwargs)
  File "teuthology/orchestra/run.py", line 423, in run
    r.wait()
  File "teuthology/orchestra/run.py", line 143, in wait
    greenlet.get()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/greenlet.py", line 465, in get
    result = self.parent.switch()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/hub.py", line 630, in switch
    return RawGreenlet.switch(self)

Greenlet <Hub at 0x1086c9050 select default pending=0 ref=1 resolver=<gevent.resolver_thread.Resolver at 0x10a05d590 pool=<ThreadPool at 0x10a05d1d0 0/1/10>> threadpool=<ThreadPool at 0x10a05d1d0 0/1/10>>
Stack:
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/gevent/hub.py", line 688, in run
    loop.run()
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/manhole.py", line 468, in handle_oneshot
    ManholeConnectionThread.handle(client, self.thread.locals)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/manhole.py", line 268, in handle
    run_repl(locals)
  File "/Users/zack/inkdev/teuthology_5/virtualenv/lib/python2.7/site-packages/manhole.py", line 323, in run_repl
    ManholeConsole(namespace).interact()
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/code.py", line 243, in i