| msg208199 - (view) |
Author: Yury Selivanov (yselivanov) *  |
Date: 2014-01-15 22:11 |
| 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). |
|
|
| msg208200 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 22:11 |
| And I'd be happy to help with the patch. |
|
|
| msg208202 - (view) |
Author: Guido van Rossum (gvanrossum) * |
Date: 2014-01-15 22:17 |
| What part of the debug timing is more expensive than the select call itself? |
|
|
| msg208203 - (view) |
Author: STINNER Victor (vstinner) * |
Date: 2014-01-15 22:19 |
| I'm also in favor of removing this code, or a debug flag to enable it. |
|
|
| msg208205 - (view) |
Author: Guido van Rossum (gvanrossum) * |
Date: 2014-01-15 22:23 |
| Can you check for the level of the logger? That would work for me. |
|
|
| msg208206 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 22:24 |
| > 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 |
|
|
| msg208207 - (view) |
Author: Guido van Rossum (gvanrossum) * |
Date: 2014-01-15 22:29 |
| So you admit you just want to optimize prematurely? |
|
|
| msg208208 - (view) |
Author: STINNER Victor (vstinner) * |
Date: 2014-01-15 22:38 |
| > 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. |
|
|
| msg208209 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 22:39 |
| 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. |
|
|
| msg208210 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 22:40 |
| The micro-benchmark i used is here: https://gist.github.com/1st1/8446175 |
|
|
| msg208211 - (view) |
Author: STINNER Victor (vstinner) * |
Date: 2014-01-15 23:00 |
| > 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. |
|
|
| msg208212 - (view) |
Author: Guido van Rossum (gvanrossum) * |
Date: 2014-01-15 23:03 |
| 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(). |
|
|
| msg208213 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 23:09 |
| > 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) |
|
|
| msg208214 - (view) |
Author: STINNER Victor (vstinner) * |
Date: 2014-01-15 23:16 |
| 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. |
|
|
| msg208215 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 23:16 |
| > 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. |
|
|
| msg208216 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 23:18 |
| 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) ? |
|
|
| msg208217 - (view) |
Author: Guido van Rossum (gvanrossum) * |
Date: 2014-01-15 23:18 |
| 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 . |
|
|
| msg208218 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 23:20 |
| And, I think that "asyncio._DEBUG" or even "asyncio.DEBUG" would be a great idea. |
|
|
| msg208219 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 23:24 |
| 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. |
|
|
| msg208220 - (view) |
Author: STINNER Victor (vstinner) * |
Date: 2014-01-15 23:30 |
| I opened an issue to propose asyncio.DEBUG: BaseEventLoop._run_once() |
|
|
| msg208221 - (view) |
Author: Guido van Rossum (gvanrossum) * |
Date: 2014-01-15 23:31 |
| 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? |
|
|
| msg208222 - (view) |
Author: STINNER Victor (vstinner) * |
Date: 2014-01-15 23:33 |
| I opened an issue to propose asyncio.DEBUG: http://code.google.com/p/tulip/issues/detail?id=104 (woops, copy/paste failure :-)) |
|
|
| msg208223 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2014-01-15 23:36 |
| > 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. |
|
|
| msg208263 - (view) |
Author: STINNER Victor (vstinner) * |
Date: 2014-01-16 09:21 |
| > I like logger_is_enabled_for.patch. I prefer debug_flag.patch because it is faster than logger_is_enabled_for.patch (see ). 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. |
|
|
| msg208294 - (view) |
Author: STINNER Victor (vstinner) * |
Date: 2014-01-16 18:04 |
| > 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! |
|
|
| msg208586 - (view) |
Author: Roundup Robot (python-dev)  |
Date: 2014-01-20 22:56 |
| New changeset 8bb2c3ae9402 by Victor Stinner in branch 'default': Close #20275: Optimize BaseEventLoop._run_once() http://hg.python.org/cpython/rev/8bb2c3ae9402 |
|
|