tornado.gen and ExceptionStackContext make things painfully slow

[ceymard]

changing ExceptionStackContext's code to the following makes everything smooth again :

    def __init__(self, exception_handler):
        self.exception_handler = exception_handler

    def __enter__(self):
        pass
        #self.old_contexts = _state.contexts
        #_state.contexts = (self.old_contexts +
        #                   ((ExceptionStackContext, self.exception_handler),))

    def __exit__(self, type, value, traceback):
        try:
            if type is not None:
                return self.exception_handler(type, value, traceback)
        finally:
            pass
            # _state.contexts = self.old_contexts

I do not understand all the magic's that's going on here, but my problem is that the contexts, by being copied all the time can get to slow everything down to a crawl.

What am I doing wrong ? Why is there so much ExceptionStackContext being run ?

[bdarnell]

Can you post some specific code that's slower than you expect? It's been on my todo list for a while to investigate the performance of tornado.gen in general, but it would be helpful to understand what exactly you're seeing. tornado.gen is going to have some amount of overhead in comparison to hand-coded callbacks, but hopefully it's fairly small. It's possible, however, that we've got a StackContext leak or something that's causing much worse performance. This should be fairly easy to identify once we've got a reproducible test case.

[ceymard]

The idea is that I'm processing a fairly big XML file, with about 15000 'interesting' elements in it. For each of those, I sometimes check something in my MongoDB database.

I use lxml. In the for loop that iterates over the elements, I yield Tasks. In the Task'ed function, I also yield Tasks.
Performance degrades very fast.

The code in question is part of a big system from which it would be hard to extract the incriminated part.

I will try to find time to write something that approximates it, but I have to find time.

[alekstorm]

I think I can guess what's happening. Even though your code looks procedurally like a loop, each yielded Task creates a new stack frame when its callback is executed. Since the Task refers to another function wrapped with gen.engine, this function is called inside a new ExceptionStackContext. When control finally returns to your loop, you're still inside the ExceptionStackContext - every iteration of the loop adds another level (or more, if you're calling multiple gen.engine-decorated functions). The kicker is that entering a new ExceptionStackContext copies the current list of StackContexts, which is of at least length 15000 - these are the lines you commented out.

I haven't confirmed this, however.

[bdarnell]

Yep, that'll do it. We've seen similar issues before and the fix was to call stack_context.wrap earlier (9ec87c2). But in this case there's no good place to grab the context because gen.engine is creating the StackContext, but it doesn't know what the callback is. I suppose it could work by convention and look for a kwarg named callback (a convention that is made more entrenched by gen.Task), but that's pretty ugly. Maybe I should revisit the idea of an explicit stack_context.pop function.

[ceymard]

So, where should I grap the stack context ?
Directly in the @engine part ?

[bdarnell]

Yes, to fix this problem the way we did with HTTPConnection, you'd need to wrap the callback before the "with ExceptionStackContext" block in gen.engine. (This means pulling the callback out of **kwargs).

[ceymard]

I'll try that and keep you posted.

[bdarnell]

I think I've got a fix for this in 57a3f83, although it's a little messy. Please give it a try.

[ceymard]

The fix seems to be doing the job.