From f2f41809aee3e9aecc5924abc2a2415a9bfb57a5 Mon Sep 17 00:00:00 2001 From: David Wilson Date: Sat, 19 Jan 2019 15:55:52 +0000 Subject: [PATCH] issue #459: initial get_stats() implementation --- docs/changelog.rst | 4 ++ mitogen/master.py | 94 +++++++++++++++++++++++++++++++++++++---- tests/responder_test.py | 29 +++++++++++++ 3 files changed, 119 insertions(+), 8 deletions(-) diff --git a/docs/changelog.rst b/docs/changelog.rst index 7538912b..715d6383 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -324,6 +324,10 @@ Core Library shut down, preventing new messages being enqueued that will never be sent, and subsequently producing a program hang. +* `#459 `_: the beginnings of a + :meth:`mitogen.master.Router.get_stats` call has been added. The initial + statistics cover the module loader only. + * `#462 `_: Mitogen could fail to open a PTY on broken Linux systems due to a bad interaction between the glibc :func:`grantpt` function and an incorrectly mounted ``/dev/pts`` filesystem. diff --git a/mitogen/master.py b/mitogen/master.py index 1fa1ef83..25e36c8d 100644 --- a/mitogen/master.py +++ b/mitogen/master.py @@ -43,6 +43,7 @@ import pkgutil import re import string import sys +import time import threading import types import zlib @@ -583,6 +584,18 @@ class ModuleResponder(object): self._cache = {} # fullname -> pickled self.blacklist = [] self.whitelist = [''] + + #: Number of GET_MODULE messages received. + self.get_module_count = 0 + #: Total time spent in uncached GET_MODULE. + self.get_module_secs = 0.0 + #: Number of successful LOAD_MODULE messages sent. + self.good_load_module_count = 0 + #: Total bytes in successful LOAD_MODULE payloads. + self.good_load_module_size = 0 + #: Number of negative LOAD_MODULE messages sent. + self.bad_load_module_count = 0 + router.add_handler( fn=self._on_get_module, handle=mitogen.core.GET_MODULE, @@ -671,19 +684,25 @@ class ModuleResponder(object): def _send_load_module(self, stream, fullname): if fullname not in stream.sent_modules: LOG.debug('_send_load_module(%r, %r)', stream, fullname) - self._router._async_route( - mitogen.core.Message.pickled( - self._build_tuple(fullname), - dst_id=stream.remote_id, - handle=mitogen.core.LOAD_MODULE, - ) + tup = self._build_tuple(fullname) + msg = mitogen.core.Message.pickled( + tup, + dst_id=stream.remote_id, + handle=mitogen.core.LOAD_MODULE, ) + self._router._async_route(msg) stream.sent_modules.add(fullname) + if tup[2] is not None: + self.good_load_module_count += 1 + self.good_load_module_size += len(msg.data) + else: + self.bad_load_module_count += 1 def _send_module_load_failed(self, stream, fullname): + self.bad_load_module_count += 1 stream.send( mitogen.core.Message.pickled( - (fullname, None, None, None, ()), + self._make_negative_response(fullname), dst_id=stream.remote_id, handle=mitogen.core.LOAD_MODULE, ) @@ -717,13 +736,18 @@ class ModuleResponder(object): return LOG.debug('%r._on_get_module(%r)', self, msg.data) + self.get_module_count += 1 stream = self._router.stream_by_id(msg.src_id) fullname = msg.data.decode() if fullname in stream.sent_modules: LOG.warning('_on_get_module(): dup request for %r from %r', fullname, stream) - self._send_module_and_related(stream, fullname) + t0 = time.time() + try: + self._send_module_and_related(stream, fullname) + finally: + self.get_module_secs += time.time() - t0 def _send_forward_module(self, stream, context, fullname): if stream.remote_id != context.context_id: @@ -841,6 +865,60 @@ class Router(mitogen.parent.Router): persist=True, ) + def _on_broker_exit(self): + super(Router, self)._on_broker_exit() + dct = self.get_stats() + dct['self'] = self + dct['get_module_ms'] = 1000 * dct['get_module_secs'] + dct['good_load_module_size_kb'] = dct['good_load_module_size'] / 1024.0 + dct['good_load_module_size_avg'] = ( + ( + dct['good_load_module_size'] / + (float(dct['good_load_module_count']) or 1.0) + ) / 1024.0 + ) + + LOG.debug( + '%(self)r: stats:\n' + ' GET_MODULE requests: %(get_module_count)d\n' + ' GET_MODULE runtime: %(get_module_ms)d ms\n' + ' LOAD_MODULE responses: %(good_load_module_count)d\n' + ' Negative LOAD_MODULE responses: ' + '%(bad_load_module_count)d\n' + ' LOAD_MODULE total bytes sent: ' + '%(good_load_module_size_kb).02f kb\n' + ' LOAD_MODULE avg bytes sent: ' + '%(good_load_module_size_avg).02f kb' + % dct + ) + + def get_stats(self): + """ + Return performance data for the module responder. + + :returns: + + Dict containing keys: + + * `get_module_count`: Integer count of + :data:`mitogen.core.GET_MODULE` messages received. + * `get_module_secs`: Floating point total seconds spent servicing + :data:`mitogen.core.GET_MODULE` requests. + * `good_load_module_count`: Integer count of successful + :data:`mitogen.core.LOAD_MODULE` messages sent. + * `good_load_module_size`: Integer total bytes sent in + :data:`mitogen.core.LOAD_MODULE` message payloads. + * `bad_load_module_count`: Integer count of negative + :data:`mitogen.core.LOAD_MODULE` messages sent. + """ + return { + 'get_module_count': self.responder.get_module_count, + 'get_module_secs': self.responder.get_module_secs, + 'good_load_module_count': self.responder.good_load_module_count, + 'good_load_module_size': self.responder.good_load_module_size, + 'bad_load_module_count': self.responder.bad_load_module_count, + } + def enable_debug(self): """ Cause this context and any descendant child contexts to write debug diff --git a/tests/responder_test.py b/tests/responder_test.py index 5a7a636e..dd790880 100644 --- a/tests/responder_test.py +++ b/tests/responder_test.py @@ -74,6 +74,9 @@ class GoodModulesTest(testlib.RouterMixin, testlib.TestCase): # package machinery damage. context = self.router.local() self.assertEquals(256, context.call(plain_old_module.pow, 2, 8)) + self.assertEquals(1, self.router.responder.get_module_count) + self.assertEquals(1, self.router.responder.good_load_module_count) + self.assertEquals(359, self.router.responder.good_load_module_size) def test_simple_pkg(self): # Ensure success of a simple package containing two submodules, one of @@ -81,6 +84,10 @@ class GoodModulesTest(testlib.RouterMixin, testlib.TestCase): context = self.router.local() self.assertEquals(3, context.call(simple_pkg.a.subtract_one_add_two, 2)) + self.assertEquals(2, self.router.responder.get_module_count) + self.assertEquals(3, self.router.responder.good_load_module_count) + self.assertEquals(0, self.router.responder.bad_load_module_count) + self.assertEquals(537, self.router.responder.good_load_module_size) def test_self_contained_program(self): # Ensure a program composed of a single script can be imported @@ -110,6 +117,11 @@ class BrokenModulesTest(testlib.TestCase): responder._on_get_module(msg) self.assertEquals(1, len(router._async_route.mock_calls)) + self.assertEquals(1, responder.get_module_count) + self.assertEquals(0, responder.good_load_module_count) + self.assertEquals(0, responder.good_load_module_size) + self.assertEquals(1, responder.bad_load_module_count) + call = router._async_route.mock_calls[0] msg, = call[1] self.assertEquals(mitogen.core.LOAD_MODULE, msg.handle) @@ -139,12 +151,29 @@ class BrokenModulesTest(testlib.TestCase): responder._on_get_module(msg) self.assertEquals(1, len(router._async_route.mock_calls)) + self.assertEquals(1, responder.get_module_count) + self.assertEquals(0, responder.good_load_module_count) + self.assertEquals(0, responder.good_load_module_size) + self.assertEquals(1, responder.bad_load_module_count) + call = router._async_route.mock_calls[0] msg, = call[1] self.assertEquals(mitogen.core.LOAD_MODULE, msg.handle) self.assertIsInstance(msg.unpickle(), tuple) +class ForwardTest(testlib.RouterMixin, testlib.TestCase): + def test_stats(self): + # Forwarding stats broken because forwarding is broken. See #469. + c1 = self.router.local() + c2 = self.router.fork(via=c1) + + self.assertEquals(256, c2.call(plain_old_module.pow, 2, 8)) + self.assertEquals(3, self.router.responder.get_module_count) + self.assertEquals(5, self.router.responder.good_load_module_count) + self.assertEquals(28148, self.router.responder.good_load_module_size) + + class BlacklistTest(testlib.TestCase): @unittest2.skip('implement me') def test_whitelist_no_blacklist(self):