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

3 files changed, 4 insertions, 47 deletions

diff --git a/Lib/asyncio/base_events.py b/Lib/asyncio/base_events.py
index 492e377..780a061 100644
--- a/Lib/asyncio/base_events.py
+++ b/Lib/asyncio/base_events.py
@@ -1719,28 +1719,7 @@ class BaseEventLoop(events.AbstractEventLoop):
             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 95f4f6b..4224469 100644
--- a/Lib/test/test_asyncio/test_base_events.py
+++ b/Lib/test/test_asyncio/test_base_events.py
@@ -371,31 +371,6 @@ class BaseEventLoopTests(test_utils.TestCase):
         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 0000000..6f5321c
--- /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.