runtornado: Report the percentage of time spent outside the event loop

Note that on local dev servers, this will print out every half second, as
Tornado polls for file changes for autoreloading.  In production it will only
print out when network events occur.

(imported from commit adfe88879e4e446b7dfa6ee69e0a9ad013e9c4d4)

zephyr/management/commands/runtornado.py

@@ -5,6 +5,58 @@ import os
 import sys
 import tornado.web
 import logging
+import time
+from tornado import ioloop
+
+# A hack to keep track of how much time we spend working, versus sleeping in
+# the event loop.
+#
+# Creating a new event loop instance with a custom impl object fails (events
+# don't get processed), so instead we modify the ioloop module variable holding
+# the default poll implementation.  We need to do this before any Tornado code
+# runs that might instantiate the default event loop.
+
+orig_poll_impl = ioloop._poll
+
+class InstrumentedPoll(object):
+    def __init__(self):
+        self._underlying = orig_poll_impl()
+        self._times = []
+
+    # Python won't let us subclass e.g. select.epoll, so instead
+    # we proxy every method.  __getattr__ handles anything we
+    # don't define elsewhere.
+    def __getattr__(self, name):
+        return getattr(self._underlying, name)
+
+    # Call the underlying poll method, and report timing data.
+    def poll(self, timeout):
+        # Avoid accumulating a bunch of insignificant data points
+        # from short timeouts.
+        if timeout < 1e-3:
+            return self._underlying.poll(timeout)
+
+        # Record start and end times for the underlying poll
+        t0 = time.time()
+        result = self._underlying.poll(timeout)
+        t1 = time.time()
+
+        # Log this datapoint and restrict our log to the past minute
+        self._times.append((t0, t1))
+        while self._times and self._times[0][0] < t1 - 60:
+            self._times.pop(0)
+
+        # Report the percentage of time spent outside poll
+        if self._times:
+            total = t1 - self._times[0][0]
+            in_poll = sum(b-a for a,b in self._times)
+            if total > 0:
+                logging.info('Tornado %5.1f%% busy over the past %4.1f seconds'
+                    % (100 * (1 - in_poll/total), total))
+
+        return result
+
+ioloop._poll = InstrumentedPoll
 
 class Command(BaseCommand):
     option_list = BaseCommand.option_list + (
@@ -25,7 +77,7 @@ class Command(BaseCommand):
 
         import django
         from django.core.handlers.wsgi import WSGIHandler
-        from tornado import httpserver, wsgi, ioloop, web
+        from tornado import httpserver, wsgi, web
 
         try:
             addr, port = addrport.split(':')