Debugging coroutines

[Gustavo Carneiro]

While trying to find a solution for a program deadlocking in eventlet, I am wondering whether tulip programs might not face the same issue.   If you have a bunch of tulip coroutines all waiting on some network event that is never going to arrive, would it be possible to just print a stack trace for each of them?

In eventlet, you can enable stack traces with eventlet.debug.hub_listener_stacks(True), and then print the stack traces whenever you want with eventlet.debug.format_hub_listeners().  Unfortunately, enabling the stack traces incurs a performance penalty and cannot be enabled in production code.

I did not find anything similar in gevent.

In tulip, coroutines are powered by generator functions.  I wonder if we can print the stack trace of all waiting coroutines handled by tulip?  Ideally, it should be a method in the event loop class.

A quick research shows that generator objects have gi_code and gi_frame attributes, that should at least allow printing the file name and line number of each coroutine known to Tulip.  The full stack trace would be better, but it is probably too expensive to keep track of.

So I would propose a method like:

    BaseEventLoop.format_running_coroutines()

It would return a multiline string showing the state of running coroutines, based on gi_frame and gi_code, possibly some more info.

Comments?

--

Gustavo J. A. M. Carneiro

Gambit Research LLC
"The universe is always one step beyond logic." -- Frank Herbert

[Guido van Rossum]

Hmm... Presumably there's really only one task waiting directly for the network event and the others are waiting for it. I think typically you should address this in your app by explicitly adding timeouts -- e.g. instead of "yield from r.readline()" you'd write "yield from tulip.wait_for(r.readline(), timeout=15)".

I assume that getting access to the full stack trace once you have the frame isn't the problem (the stdlib traceback module can do this), but Tulip doesn't have a central registry where all pending tasks are kept, so that would be a problem. Perhaps you could create your own registry of Task objects in which you are interested? You could make it a weakset. The coroutine is t._coro, we could give you an accessor for that or a method that returns the frame or the stack trace.

--
--Guido van Rossum (python.org/~guido)

[Guido van Rossum]

Well, I spent a little time on this, and here's a patch: http://codereview.appspot.com/14295043

It's designed so that if you hg import this and then in the tulip project directory run "python3 t.py" you should see a few tracebacks.

One sad thing however is that it seems that a suspended generator only shows one stack frame.

[Gustavo Carneiro]

On Wed, Oct 2, 2013 at 6:35 PM, Guido van Rossum <gu...@python.org> wrote:

Well, I spent a little time on this, and here's a patch: http://codereview.appspot.com/14295043

It's designed so that if you hg import this and then in the tulip project directory run "python3 t.py" you should see a few tracebacks.

Thank you, Guido, it looks great.

 

One sad thing however is that it seems that a suspended generator only shows one stack frame.

Yeah, I had noticed this problem.  Still, it is really helpful that it shows the state of all coroutines, even if it doesn't show the stack trace of the creator of each coroutine/task.

If we can have this in tulip, with the introspection information being essentially free (unlike in eventlet, where activating it really makes it significantly slower), then it is a big win for tulip IMHO.

Conceivably we might allow extra debugging options, where the stack trace of where each task is created is saved in the task itself.  But to be honest that doesn't interest me much because then we would not be able to enable it in a production system.

Cheers.

[Antoine Pitrou]

On Wed, 2 Oct 2013 10:35:05 -0700
Guido van Rossum <gu...@python.org> wrote:
> Well, I spent a little time on this, and here's a patch:
> http://codereview.appspot.com/14295043
>
> It's designed so that if you hg import this and then in the tulip project
> directory run "python3 t.py" you should see a few tracebacks.
>
> One sad thing however is that it seems that a suspended generator only
> shows one stack frame.

I think that's by design. There's the following code in genobject.c,
in the part that resumes a generator:

gen->gi_running = 1;
result = PyEval_EvalFrameEx(f, exc);
gen->gi_running = 0;

/* Don't keep the reference to f_back any longer than necessary. It
* may keep a chain of frames alive or it could create a reference
* cycle. */
assert(f->f_back == tstate->frame);
Py_CLEAR(f->f_back);


Regards

Antoine.

[Guido van Rossum]

AFAICT that code is old, and I agree with it. When a generator is suspended, it may be resumed by a different frame than before.

However, perhaps we can do something different for yield from? Consider:

def foo():

    yield 1

    yield 2

def bar():

    yield from foo()

When I call bar(), and it is suspended, I only see bar's frame. (The output of t.py in the patch proves this.) I think this is because (in sufficient approximation) this is treated as:

def bar():

    for x in foo():

        yield x

which in turn is close enough to:

def bar():

    it = iter(foo())

    while True:

        try:

            x = next(it)

        except StopIteration:

            break

        yield x

So foo's frame is unlinked and relinked each time next(x) is called.

*** But because it's really a yield-from we know that it will be resumed from the same place! ***

So if we can, I would like to see foo's frame still pointing to bar's frame, even though foo is suspended. I think that would print a much more useful stack in many cases.

[Antoine Pitrou]

On Wed, 2 Oct 2013 13:53:11 -0700
Guido van Rossum <gu...@python.org> wrote:
>
> So foo's frame is unlinked and relinked each time next(x) is called.
>
> *** But because it's really a yield-from we know that it will be resumed
> from the same place! ***

Is it always the case? I don't know anything about yield from, to be
honest.

Under that condition, yes, it seems reasonable.

Regards

Antoine.

[Guido van Rossum]

On Wed, Oct 2, 2013 at 11:49 AM, Gustavo Carneiro <gjcar...@gmail.com> wrote:

On Wed, Oct 2, 2013 at 6:35 PM, Guido van Rossum <gu...@python.org> wrote:

Well, I spent a little time on this, and here's a patch: http://codereview.appspot.com/14295043

It's designed so that if you hg import this and then in the tulip project directory run "python3 t.py" you should see a few tracebacks.

Thank you, Guido, it looks great.

This is now checked in. I didn't write tests, but there's an example (examples/stack.py) that's about the same as the t.py I showed in the code review.

 

One sad thing however is that it seems that a suspended generator only shows one stack frame.

Yeah, I had noticed this problem.  Still, it is really helpful that it shows the state of all coroutines, even if it doesn't show the stack trace of the creator of each coroutine/task.

If we can have this in tulip, with the introspection information being essentially free (unlike in eventlet, where activating it really makes it significantly slower), then it is a big win for tulip IMHO.

Conceivably we might allow extra debugging options, where the stack trace of where each task is created is saved in the task itself.  But to be honest that doesn't interest me much because then we would not be able to enable it in a production system.

I'll pass on that for now. The various all_*tasks() class methods and get_stack() should let you build your own pretty easily.

[Saúl Ibarra Corretgé]

On 10/9/13 1:29 AM, Guido van Rossum wrote:
> On Wed, Oct 2, 2013 at 11:49 AM, Gustavo Carneiro <gjcar...@gmail.com
> <mailto:gjcar...@gmail.com>> wrote:
>
>
>
>
> On Wed, Oct 2, 2013 at 6:35 PM, Guido van Rossum <gu...@python.org
> <mailto:gu...@python.org>> wrote:
>
> Well, I spent a little time on this, and here's a patch:
> http://codereview.appspot.com/14295043
>
> It's designed so that if you hg import this and then in the
> tulip project directory run "python3 t.py" you should see a few
> tracebacks.
>
>
> Thank you, Guido, it looks great.
>
>
> This is now checked in. I didn't write tests, but there's an example
> (examples/stack.py) that's about the same as the t.py I showed in the
> code review.
>

Quick question: any reason why those functions operate on the global
list of tasks and not on a per-loop level?


--
Sa�l Ibarra Corretg�
http://bettercallsaghul.com

[Guido van Rossum]

I hadn't thought about that. I suppose we could add a loop parameter to the all*tasks() functions to filter tasks per loop, defaulting to the current -- although maybe you'd also want to have a way to get really all of them?

It's a debug freebie -- if you want it improved please send a patch. :-)

[Saúl Ibarra Corretgé]

>
> Quick question: any reason why those functions operate on the global
> list of tasks and not on a per-loop level?
>
>
> I hadn't thought about that. I suppose we could add a loop parameter to
> the all*tasks() functions to filter tasks per loop, defaulting to the
> current -- although maybe you'd also want to have a way to get really
> all of them?
>

TBH I don't know when / why I'd like all of them, since you are probably
interested in the ones running in a given loop. An application could
call the function for each loop it has.

> It's a debug freebie -- if you want it improved please send a patch. :-)
>

Will do :-)

[Guido van Rossum]

BTW, I think I went overboard in offering so many. Perhaps just having all_tasks() taking an optional event loop argument (defaulting to the current one) would be sufficient? I.e.

class Task(Future):
    ...

    _all_tasks = WeakSet()

    @classmethod

    def all_tasks(cls, loop=None):

        if loop is None: loop = get_event_loop()

        return {t for c in cls if t._loop is loop}

--
Saúl Ibarra Corretgé
http://bettercallsaghul.com

[Gustavo Carneiro]

On Thu, Oct 10, 2013 at 4:00 PM, Guido van Rossum <gu...@python.org> wrote:

BTW, I think I went overboard in offering so many. Perhaps just having all_tasks() taking an optional event loop argument (defaulting to the current one) would be sufficient? I.e.

class Task(Future):
    ...

    _all_tasks = WeakSet()

    @classmethod

    def all_tasks(cls, loop=None):

        if loop is None: loop = get_event_loop()

        return {t for c in cls if t._loop is loop}

+1.

Task.all_tasks() and the print_stack() method in each task should be all that you need to debug things.  I have no complaints in making it per-loop instead of global.

 

On Thu, Oct 10, 2013 at 1:01 AM, Saúl Ibarra Corretgé <sag...@gmail.com> wrote:

    Quick question: any reason why those functions operate on the global
    list of tasks and not on a per-loop level?


I hadn't thought about that. I suppose we could add a loop parameter to
the all*tasks() functions to filter tasks per loop, defaulting to the
current -- although maybe you'd also want to have a way to get really
all of them?

TBH I don't know when / why I'd like all of them, since you are probably interested in the ones running in a given loop. An application could call the function for each loop it has.

It's a debug freebie -- if you want it improved please send a patch. :-)

Will do :-)

--
Saúl Ibarra Corretgé
http://bettercallsaghul.com

--
--Guido van Rossum (python.org/~guido)

[Guido van Rossum]

OK, I'll change it this way.

[Guido van Rossum]

Done.

[Saúl Ibarra Corretgé]

On 10/10/13 8:06 PM, Guido van Rossum wrote:
> Done.
>

That was quick, thanks!