+1 to some form of slow-callback detection. Tornado's version of this idea works a little differently: it uses signal.setitimer() and logs a stack trace from the signal handler. This has the advantage that it works even for deadlocks or infinite loops that will never return normally, and it also sidesteps the problem of needing a printable representation of the callback. On the other hand, it is less portable and signals introduce their own category of bugs (including both garbled output in the logs and the fact that some common libraries do not properly retry on EINTR), so it is disabled by default and must be turned on explicitly.
For my own use, I prefer the signal-based version, but I do think it would be a good idea to have something that's safe enough to turn on by default, to help educate people who use blocking methods in on an event loop (giving them a message they can search for instead of just silently reducing the scalability of their application). -Ben On Fri, Jan 17, 2014 at 8:35 AM, Victor Stinner <[email protected]>wrote: > Hi, > > I added a section "Handle correctly blocking functions" in asyncio > documentation: > > http://docs.python.org/dev/library/asyncio-dev.html#handle-correctly-blocking-functions > > IMO slow operations should not be run directly by the event loop, but > should use an executor (run in a different thread or even if > subprocess if needed). > > It's not easy to detect "slow operations". I propose to add log > handlers taking more than 1 second to complete at the INFO level. I > proposed a patch there: > http://code.google.com/p/tulip/issues/detail?id=105 > > (Copy of my issue:) > > Attached patch logs slow handles taking more than 1 second to execute > at INFO level. It should help to detect tasks blocking the event loop > and so having an impact on the reactivity/latency. > > Use for example test_slow_operations.py to test this feature. Output: > --- > slow callback: done > INFO:asyncio:Executing Handle(<function slow_callback at > 0x7ff6e52c15f0>, ()) took 1.001 seconds > slow coroutine: done > INFO:asyncio:Executing Handle(<bound method Task._step of > Task(<coro>)<result=None>>, ()) took 1.001 seconds > --- > > Problem: the log for coroutines should be improved, but the issue is > not specific to log but to repr(Task) in general. The problem is that > repr(generator) uses generator.gi_code.co_name which is "coro". The > @coroutine uses functools.wraps() to change the name of the function, > but not the name of the code object. > > Victor >
