diff --git a/README.rst b/README.rst index 4a97993..03a55e6 100644 --- a/README.rst +++ b/README.rst @@ -44,26 +44,41 @@ OSprofiler API version 0.2.0 There are a couple of things that you should know about API before using it. -* **3 ways to add a new trace point** + +* **4 ways to add a new trace point** .. parsed-literal:: from osprofiler import profiler def some_func(): - profiler.start("point_name", {"any_info_about_point": "in_this_dict"}) + profiler.start("point_name", {"any_key": "with_any_value"}) # your code profiler.stop({"any_info_about_point": "in_this_dict"}) - @profiler.Trace("point_name", {"any_info_about_point": "in_this_dict"}) - def some_func2(): + @profiler.Trace("point_name", + info={"any_info_about_point": "in_this_dict"}, + hide_args=False) + def some_func2(*args, **kwargs): + # If you need to hide args in profile info, put hide_args=True pass def some_func3(): - with profiler.trace("point_name", {"any_info_about_point": "in_this_dict"}): + with profiler.trace("point_name", + info={"any_key": "with_any_value"}): # some code here + @profiler.trace_cls("point_name", info={}, hide_args=False, + trace_private=False) + class TracedClass(object): + + def traced_method(self): + pass + + def _traced_only_if_trace_private_true(self): + pass + * **How profiler works?** * **@profiler.Trace()** and **profiler.trace()** are just syntax sugar, diff --git a/osprofiler/profiler.py b/osprofiler/profiler.py index 2a6e5f9..514a066 100644 --- a/osprofiler/profiler.py +++ b/osprofiler/profiler.py @@ -15,6 +15,7 @@ import collections import functools +import inspect import threading import uuid @@ -73,12 +74,12 @@ def stop(info=None): def trace(name, info=None, hide_args=False): - """Trace decorator. + """Trace decorator for functions. - Very useful if you would like to add trace point on existing method: + Very useful if you would like to add trace point on existing function: >> @profiler.trace("my_point") - >> def my_method(self, some_args): + >> def my_func(self, some_args): >> #code :param name: The name of action. E.g. wsgi, rpc, db, etc.. @@ -91,13 +92,14 @@ def trace(name, info=None, hide_args=False): info = info or {} def decorator(f): - info["method"] = "%s.%s" % (f.__module__, f.__name__) @functools.wraps(f) def wrapper(*args, **kwargs): + info["function"] = {"name": _get_full_func_name(f)} + if not hide_args: - info["args"] = str(args) - info["kwargs"] = str(kwargs) + info["function"]["args"] = str(args) + info["function"]["kwargs"] = str(kwargs) with Trace(name, info=info): return f(*args, **kwargs) @@ -107,6 +109,46 @@ def trace(name, info=None, hide_args=False): return decorator +def trace_cls(name, info=None, hide_args=False, trace_private=False): + """Trace decorator for instances of class . + + Very useful if you would like to add trace point on existing method: + + >> @profiler.trace_cls("rpc") + >> RpcManagerClass(object): + >> + >> def my_method(self, some_args): + >> pass + >> + >> def my_method2(self, some_arg1, some_arg2, kw=None, kw2=None) + >> pass + >> + + :param name: The name of action. E.g. wsgi, rpc, db, etc.. + :param info: Dictionary with extra trace information. For example in wsgi + it can be url, in rpc - message or in db sql - request. + :param hide_args: Don't push to trace info args and kwargs. Quite useful + if you have some info in args that you wont to share, + e.g. passwords. + + :param trace_private: Trace methods that starts with "_". It wont trace + methods that starts "__" even if it is turned on. + """ + + def decorator(cls): + for attr_name, attr in inspect.getmembers(cls): + if not callable(attr) or attr_name.startswith("__"): + continue + if not trace_private and attr_name.startswith("_"): + continue + + setattr(cls, attr_name, + trace(name, info=info, hide_args=hide_args)(attr)) + return cls + + return decorator + + class Trace(object): def __init__(self, name, info=None): @@ -134,6 +176,17 @@ class Trace(object): stop() +def _get_full_func_name(f): + if hasattr(f, "__qualname__"): + # NOTE(boris-42): Most proper way to get full name in py33 + return ".".join([f.__module__, f.__qualname__]) + + if inspect.ismethod(f): + return ".".join([f.__module__, f.im_class.__name__, f.__name__]) + + return ".".join([f.__module__, f.__name__]) + + class _Profiler(object): def __init__(self, hmac_key, base_id=None, parent_id=None): diff --git a/tests/test_profiler.py b/tests/test_profiler.py index 677966b..726bc62 100644 --- a/tests/test_profiler.py +++ b/tests/test_profiler.py @@ -14,7 +14,9 @@ # under the License. import collections +import copy import mock +import re from osprofiler import profiler @@ -129,7 +131,7 @@ class ProfilerTestCase(test.TestCase): self.assertEqual(hmac, prof.hmac_key) -class TraceTestCase(test.TestCase): +class WithTraceTestCase(test.TestCase): @mock.patch("osprofiler.profiler.stop") @mock.patch("osprofiler.profiler.start") @@ -144,33 +146,169 @@ class TraceTestCase(test.TestCase): mock_stop.reset_mock() mock_stop.assert_called_once_with() + +@profiler.trace("function", info={"info": "some_info"}) +def tracede_func(i): + return i + + +@profiler.trace("hide_args", hide_args=True) +def trace_hide_args_func(a, i=10): + return (a, i) + + +class TraceDecoratorTestCase(test.TestCase): + @mock.patch("osprofiler.profiler.stop") @mock.patch("osprofiler.profiler.start") - def test_decorator_trace(self, mock_start, mock_stop): + def test_with_args(self, mock_start, mock_stop): + self.assertEqual(1, tracede_func(1)) + expected_info = { + "info": "some_info", + "function": { + "name": "tests.test_profiler.tracede_func", + "args": str((1,)), + "kwargs": str({}) + } + } + mock_start.assert_called_once_with("function", info=expected_info) + mock_stop.assert_called_once_with() - @profiler.trace("a", info={"b": 20}) - def method(a, b=10): - return a + b + @mock.patch("osprofiler.profiler.stop") + @mock.patch("osprofiler.profiler.start") + def test_without_args(self, mock_start, mock_stop): + self.assertEqual((1, 2), trace_hide_args_func(1, i=2)) + expected_info = { + "function": { + "name": "tests.test_profiler.trace_hide_args_func" + } + } + mock_start.assert_called_once_with("hide_args", info=expected_info) + mock_stop.assert_called_once_with() - self.assertEqual(40, method(10, b=30)) + +class FakeTracedCls(object): + + def method1(self, a, b, c=10): + return a + b + c + + def method2(self, d, e): + return d - e + + def method3(self, g=10, h=20): + return g * h + + def _method(self, i): + return i + + +@profiler.trace_cls("rpc", info={"a": 10}) +class FakeTraceClassWithInfo(FakeTracedCls): + pass + + +@profiler.trace_cls("a", info={"b": 20}, hide_args=True) +class FakeTraceClassHideArgs(FakeTracedCls): + pass + + +@profiler.trace_cls("rpc", trace_private=True) +class FakeTracePrivate(FakeTracedCls): + pass + + +def py3_info(info): + # NOTE(boris-42): py33 I hate you. + info_py3 = copy.deepcopy(info) + new_name = re.sub("FakeTrace[^.]*", "FakeTracedCls", + info_py3["function"]["name"]) + info_py3["function"]["name"] = new_name + return info_py3 + + +def possible_mock_calls(name, info): + # NOTE(boris-42): py33 I hate you. + return [mock.call(name, info=info), mock.call(name, info=py3_info(info))] + + +class TraceClsDecoratorTestCase(test.TestCase): + + @mock.patch("osprofiler.profiler.stop") + @mock.patch("osprofiler.profiler.start") + def test_args(self, mock_start, mock_stop): + fake_cls = FakeTraceClassWithInfo() + self.assertEqual(30, fake_cls.method1(5, 15)) + expected_info = { + "a": 10, + "function": { + "name": "tests.test_profiler.FakeTraceClassWithInfo.method1", + "args": str((fake_cls, 5, 15)), + "kwargs": str({}) + } + } + self.assertEqual(1, len(mock_start.call_args_list)) + self.assertIn(mock_start.call_args_list[0], + possible_mock_calls("rpc", expected_info)) + mock_stop.assert_called_once_with() + + @mock.patch("osprofiler.profiler.stop") + @mock.patch("osprofiler.profiler.start") + def test_kwargs(self, mock_start, mock_stop): + fake_cls = FakeTraceClassWithInfo() + self.assertEqual(50, fake_cls.method3(g=5, h=10)) + expected_info = { + "a": 10, + "function": { + "name": "tests.test_profiler.FakeTraceClassWithInfo.method3", + "args": str((fake_cls,)), + "kwargs": str({"g": 5, "h": 10}) + } + } + self.assertEqual(1, len(mock_start.call_args_list)) + self.assertIn(mock_start.call_args_list[0], + possible_mock_calls("rpc", expected_info)) + mock_stop.assert_called_once_with() + + @mock.patch("osprofiler.profiler.stop") + @mock.patch("osprofiler.profiler.start") + def test_without_private(self, mock_start, mock_stop): + fake_cls = FakeTraceClassHideArgs() + self.assertEqual(10, fake_cls._method(10)) + self.assertFalse(mock_start.called) + self.assertFalse(mock_stop.called) + + @mock.patch("osprofiler.profiler.stop") + @mock.patch("osprofiler.profiler.start") + def test_without_args(self, mock_start, mock_stop): + fake_cls = FakeTraceClassHideArgs() + self.assertEqual(40, fake_cls.method1(5, 15, c=20)) expected_info = { "b": 20, - "method": "tests.test_profiler.method", - "args": str((10,)), - "kwargs": str({"b": 30}) + "function": { + "name": "tests.test_profiler.FakeTraceClassHideArgs.method1" + } } - mock_start.assert_called_once_with("a", info=expected_info) + + self.assertEqual(1, len(mock_start.call_args_list)) + self.assertIn(mock_start.call_args_list[0], + possible_mock_calls("a", expected_info)) mock_stop.assert_called_once_with() @mock.patch("osprofiler.profiler.stop") @mock.patch("osprofiler.profiler.start") - def test_decorator_trace_without_args(self, mock_start, mock_stop): + def test_private_methods(self, mock_start, mock_stop): + fake_cls = FakeTracePrivate() + self.assertEqual(5, fake_cls._method(5)) - @profiler.trace("a", info={}, hide_args=True) - def method2(a, b=10): - return a + b + expected_info = { + "function": { + "name": "tests.test_profiler.FakeTracePrivate._method", + "args": str((fake_cls, 5)), + "kwargs": str({}) + } + } - self.assertEqual(30, method2(10, b=20)) - expected_info = {"method": "tests.test_profiler.method2"} - mock_start.assert_called_once_with("a", info=expected_info) + self.assertEqual(1, len(mock_start.call_args_list)) + self.assertIn(mock_start.call_args_list[0], + possible_mock_calls("rpc", expected_info)) mock_stop.assert_called_once_with()