mirror of
https://github.com/zulip/zulip.git
synced 2025-11-07 07:23:22 +00:00
7685e47f07
When we added rabbitmq usage within Tornado, we inadvertently caused the Tornado ioloop to be initialized in runtornado.py's imports, before we overwrote the _poll method. The end result was that we weren't running the our instrumented Tornado poll function. Fix this by moving that code to its own file which we import at the top of runtornado.py, and adding comments documenting the situation so we don't break this in some future import reorganization. (imported from commit 016717476f10566fef4ed2b656f29f865d2084db)
58 lines
2.0 KiB
Python
58 lines
2.0 KiB
Python
import logging
|
|
import time
|
|
from tornado import ioloop
|
|
|
|
orig_poll_impl = ioloop._poll
|
|
|
|
# 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.
|
|
|
|
class InstrumentedPoll(object):
|
|
def __init__(self):
|
|
self._underlying = orig_poll_impl()
|
|
self._times = []
|
|
self._last_print = 0
|
|
|
|
# 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 (at most once every 5s) the percentage of time spent
|
|
# outside poll
|
|
if self._times and t1 - self._last_print >= 5:
|
|
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))
|
|
self._last_print = t1
|
|
|
|
return result
|
|
|
|
def instrument_tornado_ioloop():
|
|
ioloop._poll = InstrumentedPoll
|