openstack/osprofiler
Code Issues Proposed changes

Add @profiler.trace_cls decorator

Browse Source 
* This decorator allows us to add @trace to all public (and optionally
private) methods of class.

Sample of usage

> @profiler.trace_cls("rpc", info={"any": "info"}, hide_args=False, trace_private=False)
> class SomeClass(object):
>
>     def traced_method(self, arg1, arg2):
>         pass
>
>     def _non_traced_method(self, some_arg)
>         pass

* Improved @profiler.trace decorator
  Now it set's full path path including class name of method.

* Use separated scope for method's: name, args, kwargs.
  make it much easier to read trace info

* Update read me

Change-Id: I45b0dd7c2acdfc5bf66470bd4d15872a3a379af5
This commit is contained in:
Boris Pavlovic 2014-07-12 22:23:38 +04:00
parent 2a0300dc07
commit 3c0bdc8f5b
3 changed files with 234 additions and 28 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

25
README.rst
View File

@ -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,

65
osprofiler/profiler.py
View File

@ -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):

172
tests/test_profiler.py
View File

@ -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()