https://github.com/python/cpython/commit/d5bd036138881bb90a803397d992870a46f... commit: d5bd036138881bb90a803397d992870a46fbdc2d branch: master author: Andrew Svetlov <andrew.svetlov@gmail.com> committer: Miss Islington (bot) <31488909+miss-islington@users.noreply.github.com> date: 2018-09-29T22:28:40-07:00 summary: bpo-34849: Don't log wating for selector.select in asyncio loop iteration (GH-9641) The waiting is pretty normal for any asyncio program, logging its time just adds a noise to logs without any useful information provided. https://bugs.python.org/issue34849 files: A Misc/NEWS.d/next/Library/2018-09-30-08-08-14.bpo-34849.NXK9Ff.rst M Lib/asyncio/base_events.py M Lib/test/test_asyncio/test_base_events.py diff --git a/Lib/asyncio/base_events.py b/Lib/asyncio/base_events.py index 492e377d09e0..780a06192dcf 100644 --- a/Lib/asyncio/base_events.py +++ b/Lib/asyncio/base_events.py @@ -1719,28 +1719,7 @@ def _run_once(self): when = self._scheduled[0]._when timeout = min(max(0, when - self.time()), MAXIMUM_SELECT_TIMEOUT) - if self._debug and timeout != 0: - t0 = self.time() - event_list = self._selector.select(timeout) - dt = self.time() - t0 - if dt >= 1.0: - level = logging.INFO - else: - level = logging.DEBUG - nevent = len(event_list) - if timeout is None: - logger.log(level, 'poll took %.3f ms: %s events', - dt * 1e3, nevent) - elif nevent: - logger.log(level, - 'poll %.3f ms took %.3f ms: %s events', - timeout * 1e3, dt * 1e3, nevent) - elif dt >= 1.0: - logger.log(level, - 'poll %.3f ms took %.3f ms: timeout', - timeout * 1e3, dt * 1e3) - else: - event_list = self._selector.select(timeout) + event_list = self._selector.select(timeout) self._process_events(event_list) # Handle 'later' callbacks that are ready. diff --git a/Lib/test/test_asyncio/test_base_events.py b/Lib/test/test_asyncio/test_base_events.py index 95f4f6b82d53..42244699372a 100644 --- a/Lib/test/test_asyncio/test_base_events.py +++ b/Lib/test/test_asyncio/test_base_events.py @@ -371,31 +371,6 @@ def test_set_debug(self): self.loop.set_debug(False) self.assertFalse(self.loop.get_debug()) - @mock.patch('asyncio.base_events.logger') - def test__run_once_logging(self, m_logger): - def slow_select(timeout): - # Sleep a bit longer than a second to avoid timer resolution - # issues. - time.sleep(1.1) - return [] - - # logging needs debug flag - self.loop.set_debug(True) - - # Log to INFO level if timeout > 1.0 sec. - self.loop._selector.select = slow_select - self.loop._process_events = mock.Mock() - self.loop._run_once() - self.assertEqual(logging.INFO, m_logger.log.call_args[0][0]) - - def fast_select(timeout): - time.sleep(0.001) - return [] - - self.loop._selector.select = fast_select - self.loop._run_once() - self.assertEqual(logging.DEBUG, m_logger.log.call_args[0][0]) - def test__run_once_schedule_handle(self): handle = None processed = False diff --git a/Misc/NEWS.d/next/Library/2018-09-30-08-08-14.bpo-34849.NXK9Ff.rst b/Misc/NEWS.d/next/Library/2018-09-30-08-08-14.bpo-34849.NXK9Ff.rst new file mode 100644 index 000000000000..6f5321ce4cf7 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2018-09-30-08-08-14.bpo-34849.NXK9Ff.rst @@ -0,0 +1,3 @@ +Don't log wating for ``selector.select`` in asyncio loop iteration. The +waiting is pretty normal for any asyncio program, logging its time just adds +a noise to logs without any useful information provided.