diff --git a/README.md b/README.md index 2a2d70a..fd2b79e 100644 --- a/README.md +++ b/README.md @@ -32,6 +32,8 @@ Probe (foo) = 5 18 ``` +Instruments aren't limited to recording devices! Use probes to fire off any kind of event handler. Instruments are free to maintain state themselves, or read it from somewhere else, to control their own behavior or even implement feedback mechanisms. A truly evil instrument could even alter the args/kwargs passed to a function on the fly, or call arbitrary Python code to do any number of crazy things. Consequently, it's up to you to govern what instruments are added to your environment. + ## Managers In a running system, we want to add, remove, start, and stop probes and instruments without having to code at an interactive prompt or restart the system; we do this with an InstrumentManager. Start by configuring the global diagnose.manager: diff --git a/src/diagnose/instruments.py b/src/diagnose/instruments.py index 7feb5c8..5bf523e 100644 --- a/src/diagnose/instruments.py +++ b/src/diagnose/instruments.py @@ -23,17 +23,20 @@ class Instrument(object): when constructing statsd metric names. * value: a Python expression to be evaluated; its result is the "process variable" to be used as the instrument sees fit. - * internal: If True, evaluate the value in the context of the - wrapped function (just before it returns). If False - (the default), evaluate the value in a wrapper - context, which contains the local variables: - * result: the return value of the target function - * start/end/elapsed: float times - * now: datetime.datetime.utcnow() - * args/kwargs: inputs to the target function; these are - also included in locals() by their argnames. - * frame: sys._getframe() of the patch wrapper - + * event: a string declaring when to fire the instrument, one of: + * call: evaluate the value just before calling the wrapped + function, in a context which contains the local variables: + * start: float time + * now: datetime.datetime.utcnow() + * args/kwargs: inputs to the target function; these are + also included in locals() by their argnames. + * frame: sys._getframe() of the patch wrapper + * return: the default; evaluate the value just after the wrapped + function returns, in a context with the additional locals: + * result: the return value of the target function + * end/elapsed: float times + * end: evaluate the value in the context of the wrapped function + just before it returns. * expires: a datetime, after which point the instrument will not fire, or None to mean no expiration * custom: a dict of any additional data for subclasses. May include @@ -45,23 +48,23 @@ class Instrument(object): error_expiration = datetime.datetime(1970, 1, 1) def __init__( - self, name, value, internal=False, expires=None, custom=None, mgr=None, **kwargs + self, name, value, event="return", expires=None, custom=None, mgr=None, **kwargs ): if mgr is None: mgr = diagnose.manager self.mgr = mgr self.name = name self.value = value - self.internal = internal + self.event = event self.expires = expires self.custom = custom or {} def __str__(self): - return "%s(name=%r, value=%r, internal=%r, expires=%r, custom=%r)" % ( + return "%s(name=%r, value=%r, event=%r, expires=%r, custom=%r)" % ( self.__class__.__name__, self.name, self.value, - self.internal, + self.event, self.expires, self.custom, ) diff --git a/src/diagnose/probes.py b/src/diagnose/probes.py index 9543328..08b8cc7 100644 --- a/src/diagnose/probes.py +++ b/src/diagnose/probes.py @@ -49,13 +49,14 @@ class FunctionProbe(object): When started, a FunctionProbe "monkey-patches" its target, replacing it with a wrapper function. That wrapper calls the original target - function, and then calls each instrument. If any instruments are "internal", - the probe registers a trace function (via `sys.settrace`) and then - calls those instruments just before the original target function returns; - the instrument values are evaluated in the globals and locals of that frame. - External instruments are evaluated after the function returns; they are - much less invasive since they do not call settrace, but they are - limited to reading the function's inputs, outputs, and timing. + function, calling each instrument at the event it specifies: call, end, + or return. If the event is "end", then the probe registers a trace function + (via `sys.settrace`) and then calls those instruments just before the + original target function returns; the instrument values are evaluated + in the globals and locals of that frame. "Call" and "return" instruments + are evaluated before or after the function returns; they are much less + invasive since they do not call settrace, but they are limited to reading + the function's inputs, outputs, and timing. """ def __init__(self, target, instruments=None): @@ -101,15 +102,13 @@ def probe_wrapper(*args, **kwargs): now = datetime.datetime.utcnow() hotspots = HotspotsFinder() - internals, externals = [], [] + instruments_by_event = {"call": [], "return": [], "end": []} for I in self.instruments.itervalues(): if I.expires and now > I.expires: continue if I.check_call(self, *args, **kwargs): - if I.internal: - internals.append(I) - else: - externals.append(I) + instruments_by_event[I.event].append(I) + if I.event in ("call", "return"): if "hotspots" in I.value or "hotspots" in ( I.custom.get("tags") or "" ): @@ -117,7 +116,7 @@ def probe_wrapper(*args, **kwargs): target_obj, target_func_name = self.target.rsplit(".", 1) is_unwrapped = base.func_code.co_name == target_func_name - if internals: + if instruments_by_event["end"]: # We have instruments that require evaluation in the local # context of the function. Call sys.settrace() to gain access. predicate = hunter.When( @@ -142,7 +141,7 @@ def probe_wrapper(*args, **kwargs): # that without a custom Cython Query. module_in=target_obj, ), - TraceHandler(self, internals), + TraceHandler(self, instruments_by_event["end"]), ) tracer = hunter.Tracer( # There's no need to call threading.settrace() because @@ -193,18 +192,10 @@ def probe_wrapper(*args, **kwargs): tracer = None try: - start = time.time() - result = base(*args, **kwargs) - if hotspots.enabled: - hotspots.finish() - end = time.time() - elapsed = end - start - if externals: + if instruments_by_event["call"] or instruments_by_event["return"]: + start = time.time() _locals = { - "result": result, "start": start, - "end": end, - "elapsed": elapsed, "now": now, "args": args, "kwargs": kwargs, @@ -218,14 +209,39 @@ def probe_wrapper(*args, **kwargs): # Add kwargs to locals _locals.update(kwargs) - for instrument in externals: + for instrument in instruments_by_event["call"]: + try: + instrument.fire(instrument.mgr.global_namespace, _locals) + except: try: - instrument.fire(instrument.mgr.global_namespace, _locals) + instrument.handle_error(self) except: - try: - instrument.handle_error(self) - except: - traceback.print_exc() + traceback.print_exc() + + # Execute the base function and obtain its result. + result = base(*args, **kwargs) + + if hotspots.enabled: + hotspots.finish() + + if instruments_by_event["return"]: + end = time.time() + elapsed = end - start + _locals.update({ + "result": result, + "end": end, + "elapsed": elapsed, + }) + + for instrument in instruments_by_event["return"]: + try: + instrument.fire(instrument.mgr.global_namespace, _locals) + except: + try: + instrument.handle_error(self) + except: + traceback.print_exc() + return result finally: if tracer is not None: diff --git a/tests/__init__.py b/tests/__init__.py index 33341ae..6137276 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -12,7 +12,7 @@ class ProbeTestCase(unittest.TestCase): @contextmanager - def probe(self, type, name, target, value, lifespan=1, custom=None, internal=False): + def probe(self, type, name, target, value, lifespan=1, custom=None, event="return"): mgr = diagnose.manager instrument_id = None try: @@ -23,7 +23,7 @@ def probe(self, type, name, target, value, lifespan=1, custom=None, internal=Fal "type": type, "name": name, "value": value, - "internal": internal, + "event": event, "custom": custom or {}, }, "lifespan": lifespan, diff --git a/tests/test_instruments.py b/tests/test_instruments.py index b83e4a2..862169b 100644 --- a/tests/test_instruments.py +++ b/tests/test_instruments.py @@ -136,26 +136,26 @@ def test_multiple_instruments(self): mgr = diagnose.manager try: target = "diagnose.test_fixtures.a_func" - mgr.specs["a_func_internal"] = { + mgr.specs["a_func_end"] = { "target": target, "instrument": { "type": "hist", - "name": "a_func_internal", + "name": "a_func_end", "value": "output", - "internal": True, + "event": "end", "custom": {}, }, "lifespan": 1, "lastmodified": datetime.datetime.utcnow(), "applied": {}, } - mgr.specs["a_func_external"] = { + mgr.specs["a_func_return"] = { "target": target, "instrument": { "type": "hist", - "name": "a_func_external", + "name": "a_func_return", "value": "result", - "internal": False, + "event": "return", "custom": {}, }, "lifespan": 1, @@ -165,8 +165,8 @@ def test_multiple_instruments(self): mgr.apply() result = a_func(78) finally: - mgr.specs.pop("a_func_internal", None) - mgr.specs.pop("a_func_external", None) + mgr.specs.pop("a_func_end", None) + mgr.specs.pop("a_func_return", None) mgr.apply() # The call MUST succeed. @@ -174,8 +174,8 @@ def test_multiple_instruments(self): # The instruments MUST each have logged an entry assert statsd.method_calls == [ - call.histogram("a_func_internal", 91, tags=[]), - call.histogram("a_func_external", 91, tags=[]), + call.histogram("a_func_end", 91, tags=[]), + call.histogram("a_func_return", 91, tags=[]), ] def test_replace_instrument(self): @@ -189,7 +189,7 @@ def test_replace_instrument(self): "type": "hist", "name": "a_func", "value": "arg", - "internal": False, + "event": "return", "custom": {}, }, "lifespan": 1, diff --git a/tests/test_probes.py b/tests/test_probes.py index aa1114c..abba4d2 100644 --- a/tests/test_probes.py +++ b/tests/test_probes.py @@ -1,6 +1,7 @@ from collections import defaultdict import datetime import gc +import sys import time import types @@ -32,10 +33,10 @@ registry = {} -class TestExternalProbe(ProbeTestCase): - def test_external_probe_result(self): +class TestReturnEvent(ProbeTestCase): + def test_return_event_result(self): with self.probe( - "test", "do", "diagnose.test_fixtures.Thing.do", "result", internal=False + "test", "do", "diagnose.test_fixtures.Thing.do", "result" ) as p: result = Thing().do("ok") @@ -44,9 +45,9 @@ def test_external_probe_result(self): # The probe MUST have logged an entry assert p.instruments.values()[0].results == [([], "")] - def test_external_probe_elapsed(self): + def test_return_event_elapsed(self): with self.probe( - "test", "do", "diagnose.test_fixtures.Thing.do", "elapsed", internal=False + "test", "do", "diagnose.test_fixtures.Thing.do", "elapsed" ) as p: start = time.time() result = Thing().do("ok") @@ -57,13 +58,12 @@ def test_external_probe_elapsed(self): # The probe MUST have logged an entry assert p.instruments.values()[0].results[0][1] < elapsed - def test_external_probe_locals(self): + def test_return_event_locals(self): with self.probe( "test", "do", "diagnose.test_fixtures.Thing.do", "sorted(locals().keys())", - internal=False, ) as p: result = Thing().do("ok") @@ -88,7 +88,7 @@ def test_external_probe_locals(self): ) ] - def test_external_caller(self): + def test_return_event_locals_frame(self): probe = probes.attach_to("diagnose.test_fixtures.a_func") try: probe.start() @@ -96,26 +96,89 @@ def test_external_caller(self): expires=datetime.datetime.utcnow() + datetime.timedelta(minutes=10), name="a_func", value="frame.f_back.f_code.co_name", - internal=False, custom=None, ) a_func(923775) - assert probe.instruments["instrument1"].results, ["test_external_caller"] + assert probe.instruments["instrument1"].results, ["test_locals_frame"] finally: probe.stop() - def test_probe_bad_mock(self): - p = probes.attach_to("diagnose.test_fixtures.Thing.notamethod") - with self.assertRaises(AttributeError) as exc: - p.start() - assert ( - exc.exception.message - == "diagnose.test_fixtures.Thing does not have the attribute 'notamethod'" - ) +class TestCallEvent(ProbeTestCase): + def test_call_event_args(self): + with self.probe( + "test", "do", "diagnose.test_fixtures.Thing.do", "args", event="call" + ) as p: + t = Thing() + result = t.do("ok") + + assert result == "" + + # The probe MUST have logged an entry + assert p.instruments.values()[0].results == [([], (t, "ok"))] + + def test_call_event_elapsed(self): + with self.probe( + "test", "do", "diagnose.test_fixtures.Thing.do", "elapsed", event="call" + ) as p: + errs = [] + p.instruments.values()[0].handle_error = lambda probe: errs.append(sys.exc_info()[1].message) + result = Thing().do("ok") + + assert result == "" + + # The probe MUST NOT have logged an entry... + assert p.instruments.values()[0].results == [] + # ...but the instrument MUST have handled the error: + assert errs == ["name 'elapsed' is not defined"] -class TestInternalProbe(ProbeTestCase): - def test_internal_instrument(self): + def test_call_event_locals(self): + with self.probe( + "test", + "do", + "diagnose.test_fixtures.Thing.do", + "sorted(locals().keys())", + event="call" + ) as p: + result = Thing().do("ok") + + assert result == "" + + # The probe MUST have logged an entry + assert p.instruments.values()[0].results == [ + ( + [], + [ + "arg", + "args", + "frame", + "kwargs", + "now", + "self", + "start", + ], + ) + ] + + def test_call_event_locals_frame(self): + probe = probes.attach_to("diagnose.test_fixtures.a_func") + try: + probe.start() + probe.instruments["instrument1"] = ProbeTestInstrument( + expires=datetime.datetime.utcnow() + datetime.timedelta(minutes=10), + name="a_func", + value="frame.f_back.f_code.co_name", + event="call", + custom=None, + ) + a_func(923775) + assert probe.instruments["instrument1"].results, ["test_locals_frame"] + finally: + probe.stop() + + +class TestEndEvent(ProbeTestCase): + def test_end_event_success(self): probe = probes.attach_to("diagnose.test_fixtures.a_func") try: probe.start() @@ -123,7 +186,7 @@ def test_internal_instrument(self): expires=datetime.datetime.utcnow() + datetime.timedelta(minutes=10), name="a_func", value="output", - internal=True, + event="end", custom=None, ) assert a_func(27) == 40 @@ -131,7 +194,7 @@ def test_internal_instrument(self): finally: probe.stop() - def test_internal_exception_in_target(self): + def test_end_event_exception_in_target(self): probe = probes.attach_to("diagnose.test_fixtures.a_func") try: probe.start() @@ -139,7 +202,7 @@ def test_internal_exception_in_target(self): expires=datetime.datetime.utcnow() + datetime.timedelta(minutes=10), name="a_func", value="extra", - internal=True, + event="end", custom=None, ) with self.assertRaises(TypeError): @@ -148,21 +211,26 @@ def test_internal_exception_in_target(self): finally: probe.stop() - def test_internal_exception_in_value(self): + def test_end_event_exception_in_value(self): probe = probes.attach_to("diagnose.test_fixtures.a_func") try: + errs = [] + old_handle_error = diagnose.manager.handle_error + diagnose.manager.handle_error = lambda probe, instr: errs.append(sys.exc_info()[1].message) probe.start() probe.instruments["instrument1"] = i = ProbeTestInstrument( expires=datetime.datetime.utcnow() + datetime.timedelta(minutes=10), name="a_func", value="unknown", # Should throw NameError - internal=True, + event="end", custom=None, ) assert a_func(1000) == 1013 assert i.results == [] assert i.expires == i.error_expiration + assert errs == ["name 'unknown' is not defined"] finally: + diagnose.manager.handle_error = old_handle_error probe.stop() @@ -175,7 +243,6 @@ def test_slowest_line(self): expires=datetime.datetime.utcnow() + datetime.timedelta(minutes=10), name="hard_work.slowest.time", value="hotspots.worst.time", - internal=False, custom={ "tags": '{"source": "%s:%s" % (hotspots.worst.lineno, hotspots.worst.source)}' }, @@ -189,7 +256,8 @@ def test_slowest_line(self): probe.stop() def test_hotspot_overhead(self): - # Set SCALE to 5000 or something big to see how overhead diminishes. + # Set SCALE to 5000 or something big to see how hotspot overhead + # diminishes the more work the target function does. # It's low in this test suite because people like fast tests. SCALE = 100 val = [dict((str(i), i) for i in xrange(100))] * SCALE @@ -204,7 +272,6 @@ def test_hotspot_overhead(self): expires=datetime.datetime.utcnow() + datetime.timedelta(minutes=10), name="to_columns.slowest.time", value="hotspots.worst.time", - internal=False, custom={ "tags": '{"source": "%s:%s" % (hotspots.worst.lineno, hotspots.worst.source)}' }, @@ -216,7 +283,7 @@ def test_hotspot_overhead(self): probe.stop() print( - "UNPATCHED: %s PATCHED: %s (%s%%)" + "\nUNPATCHED: %s PATCHED: %s (%s%%)" % (unpatched, patched, int((patched / unpatched) * 100)) ) @@ -231,7 +298,16 @@ def owner_types(obj): return num_instances -class TestTargetCopies(ProbeTestCase): +class TestTargets(ProbeTestCase): + def test_probe_bad_mock(self): + p = probes.attach_to("diagnose.test_fixtures.Thing.notamethod") + with self.assertRaises(AttributeError) as exc: + p.start() + assert ( + exc.exception.message + == "diagnose.test_fixtures.Thing does not have the attribute 'notamethod'" + ) + def test_target_copies(self): # When module M chooses "from x import y", then mock.patching x.y # does not affect M.y. Similarly, an existing object instance I @@ -261,7 +337,6 @@ class Entity(object): expires=datetime.datetime.utcnow() + datetime.timedelta(minutes=10), name="func_2", value="arg", - internal=False, custom=None, ) @@ -348,6 +423,27 @@ def test_probe_nonfunc(self): with self.assertRaises(TypeError): p.start() + def test_patch_staticmethod(self): + with self.probe( + "test", + "quantile", + "diagnose.test_fixtures.Thing.static", + "result", + ) as p: + assert Thing().static() == 15 + assert p.instruments.values()[0].results == [([], 15)] + + def test_patch_wrapped_function_end_event(self): + probe = probes.attach_to("diagnose.test_fixtures.Thing.add5") + try: + probe.start() + instr = ProbeTestInstrument("deco", "arg1", event="end") + probe.instruments["deco"] = instr + Thing().add5(13) + assert instr.results == [([], 113)] + finally: + probe.stop() + class TestProbeCheckCall(ProbeTestCase): def test_probe_check_call(self): @@ -370,30 +466,6 @@ def only_some_users(probe, instrument, *args, **kwargs): assert p.instruments.values()[0].results == [([], "")] -class TestProbePatching(ProbeTestCase): - def test_patch_staticmethod(self): - with self.probe( - "test", - "quantile", - "diagnose.test_fixtures.Thing.static", - "result", - internal=False, - ) as p: - assert Thing().static() == 15 - assert p.instruments.values()[0].results == [([], 15)] - - def test_patch_wrapped_function_internal(self): - probe = probes.attach_to("diagnose.test_fixtures.Thing.add5") - try: - probe.start() - instr = ProbeTestInstrument("deco", "arg1", internal=True) - probe.instruments["deco"] = instr - Thing().add5(13) - assert instr.results == [([], 113)] - finally: - probe.stop() - - class TestHardcodedProbes(ProbeTestCase): def test_hardcoded_probes(self): diagnose.manager.apply()