Tracer.depth = 0 but Cython Tracer.depth = 1

[aminusfu]

This causes a predicate with depth=X to fire differently depending on whether the Cython is compiled or not, or whether PUREPYTHONHUNTER is defined.

[ionelmc]

Hmmm I thought I got it right. You're looking at the source code or do you have a test case?

[aminusfu]

The source code clearly differs, and probably for a good reason. I discovered the difference while writing the following code. My goal is to have a way to measure things in production systems without having to rewrite (and rebuild/redeploy) the code being measured in any way. To accomplish this, I hope to mock.patch a method at runtime and read its local variables on return:

import functools
import traceback

import hunter
import mock

def FunctionProbe(target, action):
    """Return a mock._patch object which wraps the given function."""
    action._probe_target = target
    p = mock.patch(target)

    # Replace the target with a wrapper that starts and stops a hunter.Tracer
    original, local = p.get_original()
    # Only trace returns and only in the given function (no deeper).
    predicate = hunter.When(
        hunter.Query(
            kind="return",
            depth=hunter.Tracer().depth + 1
        ), action
    )

    @functools.wraps(original)
    def tracing_wrapper(*args, **kwargs):
        tracer = hunter.Tracer().trace(predicate)
        try:
            return original(*args, **kwargs)
        finally:
            tracer.stop()

    p.new = tracing_wrapper
    return p

class PrintValue(hunter.Action):
    """Print the given value if not None."""

    def __init__(self, value_getter):
        self.value_getter = value_getter

    def __call__(self, event):
        try:
            v = self.value_getter(event)
        except:
            print
            print "---> (%s) ERROR" % (self._probe_target,)
            print traceback.format_exc()
        else:
            print
            print "---> (%s) = %s" % (self._probe_target, v)

# To be run elsewhere...
p = FunctionProbe(
    "module.path.to.my.function",
    PrintValue(lambda event: len(event.locals.get("name_of_a_local_var", set())) or None)
)
p.start()

Feel free to use this for a cookbook entry or even steal it for hunter itself if you like. It's not very useful to package on its own since most of the work will be interfacing with logging//reporting tools and control interfaces.

An earlier version of this used hunter.wrap which calls hunter.trace. That worked fine when supplying depth=1. But I chose to unpack those because I didn't want the global _last_tracer or atexit handler. When I switched to instantiating a Tracer directly, I had to fudge the depth as above based on which Tracer was in use. I suspect that the depth difference is to fix some problem found when using hunter.wrap or hunter.trace with the Cython versus pure python classes, but is a fix that may have been applied at the wrong layer? It's also possible that I'm calling it wrong and can't tell.

[ionelmc]

Hmmm ... looks like I didn't expect people would use the tracer classes directly. I'll try to capture this usecase in the test suite and maybe there's a way to fix the depth problem differently.

Btw, what sort of codebase are you using this on? mock.patch will only work with module attributes (did you look at aspectlib.weave?)

Another thing: this should work as well:

p = FunctionProbe(
    "module.path.to.my.function",
    VarsPrinter("name_of_a_local_var.__len__()")
)

(len(name_of_a_local_var) doesn't work cause builtins are not included, not yet)

[ionelmc]

Another idea worth mentioning: you could do without any monkeypatching, eg (didn't test):

def FunctionProbe(target, action):
    mod, func = target.rsplit(1)
    predicate = hunter.When(
        hunter.Query(
            kind="return",
            module=mod,
            function=func,
        ), action
    )

[aminusfu]

mock.patch is working just fine. The builtin hunter actions aren't really useful to me since this is a distributed system; my real-world use case will send metrics to Datadog.

It's true I don't need to eval a lambda, but I do still need to handle the case where the local variable hasn't been bound yet, or doesn't have a len, etc. The complexities are endless.

However, because this will be used in production (and only for limited periods), it seems better to monkeypatch one function than set a tracer for the whole runtime and let it filter--even a nice fast Cython one (thanks for making it!)

[aminusfu]

Thanks!

[ionelmc]

@aminusfu I just noticed you had depth=hunter.Tracer().depth + 1 in your example - that seems odd. It would be the same as depth=1 because for a new tracer depth starts from 0.

Also, another quirk is that the tracer doesn't do the filtering itself, thus it can't special-case the depth filter, thus the tracer will be active even in deeper function calls.

[aminusfu]

Tracer depth starts from 0 since you fixed it in https://github.com/ionelmc/python-hunter/commit/3a22d5ad8b21079174903ad0c94da4d5876631d4 :) Now I don't need that +1 anymore.

Hunter has been working really well for this project (with that change). Thanks again for making it!

[ionelmc]

@aminusfu hehe thanks. Just curious, what sort of metrics are you pulling out of that function you trace?

[aminusfu]

I've built a module which I use daily in production to measure dark code. Any Python function, any measurement, without waiting for a deployment phase (or a second one to take out the instrumentation when I'm done). Answers in minutes, not hours or days. For example, today I measured how long some of our API requests were blocked waiting on others, broken down by which "others" were most damaging, which I will then stick into a research paper and use to help guide our roadmap.

[aminusfu]

Now open source! See https://github.com/Crunch-io/diagnose