Can we remove debug timing around "self._selector.select(timeout)"
(or at least make it configurable) from BaseEventLoop?

Right now the code is:

        # TODO: Instrumentation only in debug mode?
        t0 = self.time()
        event_list = self._selector.select(timeout)
        t1 = self.time()
        argstr = '' if timeout is None else ' {:.3f}'.format(timeout)
        if t1-t0 >= 1:
            level = logging.INFO
        else:
            level = logging.DEBUG
        logger.log(level, 'poll%s took %.3f seconds', argstr, t1-t0)

So it makes two 'time.time()' calls per loop iteration, plus
one "logging.log" call.

The only non-intrusive solution that I can suggest is to add a
class attribute '_debug' to BaseEventLoop, set to False by default
(unittests can set it to True in their setUp methods).

And I'd be happy to help with the patch.

What part of the debug timing is more expensive than the select call itself?

I'm also in favor of removing this code, or a debug flag to enable it.

Can you check for the level of the logger? That would work for me.

> What part of the debug timing is more expensive than the select call itself?

Well, there is nothing really expensive there, but:

- time.monotonic() is still a syscall
- logging.log executes a fair amount of code too

So you admit you just want to optimize prematurely?

> So you admit you just want to optimize prematurely?

I don't understand the purpose of these timing information, I don't use them. I would be more interested to know which functions take longer than XXX ms and so hangs the event loop.

By the way, it's not documentation how to enable asyncio logs:
http://docs.python.org/dev/library/asyncio.html

The asyncio logger is not documented. I would like to add a section listing development tools like asyncio.tasks._DEBUG=True and the "Future/Task exception was never retrieved" log.

Hum, it looks like asyncio.futures.STACK_DEBUG is not used.

I wrote a small micro-benchmark, that creates 100K tasks and executes them.

With debug code the execution time is around 2.8-3.1s, with debug comment commented out it's around 2.3-2.4s.

Again, it's a micro-benchmark, and in a real application the impact is going to be much smaller.

The micro-benchmark i used is here: https://gist.github.com/1st1/8446175

> With debug code the execution time is around 2.8-3.1s, with debug comment commented out it's around 2.3-2.4s.

Wow, that's impressive that such minor syscalls can take so much times!

I modified your script to repeat the test 5 times and take the minimum timing:

* Python 3.4 original: 3.83 seconds
* asyncio without timing log: 2.79 seconds (27% faster)

27% faster is not a "premature" optimisation :-)

By the way, Linux provides faster clocks like CLOCK_MONOTONIC_COARSE:

   A  faster  but  less  precise version of CLOCK_MONOTONIC.
   Use when you need very fast, but not  fine-grained  time‐
   stamps.

Python doesn't expose these clock identifiers yet: #14555.

I have definitely used this log message.  It typically tells me that something is responding too slow.

Regarding the microbench, please count and report how many times it actually calls select().

> Wow, that's impressive that such minor syscalls can take so much times!

Apparently, it's not syscalls, it's logging.

Actually, with commented out "logging.log" code I can't see a difference wether there are calls to monotonic or not.

So we can keep the code as is, let's just log something when select takes longer than 1 second (and log nothing when it's faster)

Here are two patches:

- logger_is_enabled_for.patch: use logger.isEnabledFor(INFO) to avoid the call
- add a _debug flag to BaseEventLoop

Benchmark:

- original: 3.90
- logger: 3.04
- _debug: 2.81

I like the _debug flag because it's faster, but I'm not sure that an attribute is the best place for the flag. asyncio needs maybe one global debug flag (ex: asyncio._DEBUG=True) replacing the existing asyncio.tasks._DEBUG flag.

> Regarding the microbench, please count and report how many times it actually calls select().

I'm on MacOS X, so it's KqueueSelector. It's 'select' method (and self._kqueue.control respectively) is called twice more times. So for 100K tasks, select gets called 200K. But that's just the way my benchmark is written.

Victor,

Re your patch: since it's not really time syscalls, and Guido said he's using this debug code, how about we just have something like:

        t0 = self.time()
        event_list = self._selector.select(timeout)
        t1 = self.time()
        if t1 - t0 >= 1:
            argstr = '' if timeout is None else ' {:.3f}'.format(timeout)
            level = logging.INFO
            logger.log(level, 'poll%s took %.3f seconds', argstr, t1-t0)

?

I like logger_is_enabled_for.patch.

If you want to add other debug features please propose something on the Tulip tracker: http://code.google.com/p/tulip/issues/list .

And, I think that "asyncio._DEBUG" or even "asyncio.DEBUG" would be a great idea.

Victor, Guido,

Please take a look at the attached one.
I believe it's slightly better, than the "logger_is_enabled_for.patch", since it doesn't log stuff that was faster than 1 second, and is simpler too.

I opened an issue to propose asyncio.DEBUG:
BaseEventLoop._run_once()

I really want to log the time every time if level == DEBUG and only if > 1 sec for other levels, so maybe all you need to do is remove the comment? :-)  (Or maybe logger.isEnabledFor(logging.INFO) is faster than logger.log() when nothing gets logged?

I opened an issue to propose asyncio.DEBUG:
http://code.google.com/p/tulip/issues/detail?id=104

(woops, copy/paste failure :-))

> I really want to log the time every time if level == DEBUG and only if > 1 sec for other levels, so maybe all you need to do is remove the comment? :-)  (Or maybe logger.isEnabledFor(logging.INFO) is faster than logger.log() when nothing gets logged?

Well, in this case, I think if async.DEBUG is accepted, than Victor can apply his "debug_flag.patch" (with some modifications), and if not, then his "logger_is_enabled_for.patch" would work for you too.

> I like logger_is_enabled_for.patch.

I prefer debug_flag.patch because it is faster than logger_is_enabled_for.patch (see msg208214). I would like to write the most efficient code for BaseEventLoop._run_once() because this function is the real core of asyncio and it is called very frequently.

Test attached event_loop_run_once.py script. On such dummy example, _run_once() is called 4 times.

Note: Thanks to the nice design of yield from, wrapper() doesn't add an extra call to _run_once()!


Please think also to Trollius (port of asyncio on Python 2) which uses yield instead of yield-from. The same example calls _run_once() 10 times! The wrapper itself uses 2 calls. I don't know yet if Trollius can be modified to call _run_once() less frequently. It may be hard to keep the scheduling fair between concurrent running tasks.

> I don't understand the purpose of these timing information, (...)
> By the way, it's not documentation how to enable asyncio logs

I added a new page in the asyncio documentation to start documenting common traps with asynchronous programming and to document debug tools.

I didn't document this specific log discussed in this issue. It may be documented in the "Handle correctly blocking functions" section or it may deserve a new section.

Don't hesitate to improve the asyncio documentation!

New changeset 8bb2c3ae9402 by Victor Stinner in branch 'default':
Close #20275: Optimize BaseEventLoop._run_once()
http://hg.python.org/cpython/rev/8bb2c3ae9402