PythonでPHPのXdebugみたいなプロファイラ作った

作ってみたのはいいけど、WSGIで正しく動かない。
あと動作が遅い。
 

xdebug.py

# set encoding=utf-8

import inspect
import types
from time import time
import re
import traceback
import logging


classname_reg = re.compile(r"<class '([^']+)'>")

class Xdebug(object):
    applied_module = set()
    applied_class = set()
    applied_method = {}
    original = {}
    dummy = None

    def __init__(self):
        self.call_depth = 0
        self.log = []
        self.enabled = set()

    # enable
    def enable(self, value):
        self._enable(value)

    def enable_with_submodule(self, value):
        root = None
        try:
            root = obj.__file__
            root = re.sub('/__init__\.pyc?$', '/', root)
        except:
            pass
        self._enable(value, root=root)

    def enable_with_all(self, value):
        self._enable(value, all=True)

    def _enable(self, value, root=None, all=False):
        cls = self.__class__

        # dict
        if isinstance(value, dict):
            for k,v in value.iteritems():
                if inspect.ismodule(v):
                    self._enable(v, root, all)
                elif inspect.isclass(v):
                    self._enable(v, root, all)
                elif inspect.ismethod(v) or inspect.isfunction(v):
                    self._enable(v, root, all)
        # list
        elif isinstance(value, (list, tuple, set, frozenset)):
            for v in value:
                self._enable(v, root, all)

        # module
        elif inspect.ismodule(value):
            value = cls.divide_attr(value)

            # module
            for k, v in value['module'].iteritems():
                if all or root and getattr(v, '__file__', '/').startswith(root):
                    self._enable(v, root, all)

            # class
            for k, v in value['class'].iteritems():
                self._enable(v, root, all)

            # method
            # todo

        # class
        elif inspect.isclass(value):
            if issubclass(Xdebug, value):
                return

            if value==traceback:
                return

            attr = cls.divide_attr(value)

            # classmethod
            for k, v in attr['classmethod'].iteritems():
                v = cls.classmethod_wrap(v)
                setattr(value, k, v)
                self.enabled.add(cls.original[v])

            # instancemethod
            for k, v in attr['instancemethod'].iteritems():
                v = cls.instancemethod_wrap(v)
                setattr(value, k, v)
                self.enabled.add(cls.original[v])

            # function
            #for k, v in attr['function'].iteritems():
            #    setattr(value, k, cls.function_wrap(v))

    # run
    def run(self, func, *args, **kwds):
        return func(*args, **kwds)

    # result
    def get_result(self):
        result = "TIME    METHOD\n"
        result += "\n".join(self.log)
        return result

    @classmethod
    def getmembers(cls, object):
        results = []
        for key in dir(object):
            try:
                value = getattr(object, key)
                results.append((key, value))
            except:
                pass
        results.sort()
        return results

    @classmethod
    def divide_attr(cls, module):
        result = {
            'module': {},
            'class': {},
            'classmethod': {},
            'instancemethod': {},
            'function': {},
        }
        for k, v in cls.getmembers(module):
            if k!='__init__' and k.startswith('__') and k.endswith('__'):
                continue
            if inspect.ismodule(v):
                result['module'][k] = v
            elif inspect.isclass(v):
                result['class'][k] = v
            elif inspect.ismethod(v) and v.im_self is not None:
                result['classmethod'][k] = v
            elif inspect.ismethod(v) and v.im_self is None:
                result['instancemethod'][k] = v
            elif inspect.isfunction(v):
                result['function'][k] = v
        return result

    @classmethod
    def select_instance(cls):
        framerecords = inspect.stack()
        for framerecord in framerecords:
            try:
                frame = framerecord[0]
                arginfo = inspect.getargvalues(frame)
                frame_self = arginfo.locals['self']
                if issubclass(Xdebug, frame_self.__class__):
                    return frame_self
            except:
                pass
        #raise Exception('select error: %s' % [f[0] for f in framerecords])
        return cls.get_dummy()

    @classmethod
    def get_dummy(cls):
        if cls.dummy is None:
            cls.dummy = cls()
        self = cls.dummy
        # delete
        self.call_depth = 0
        del self.log[:]
        self.enabled.clear()
        return self

    @classmethod
    def classmethod_wrap(cls, method):
        if method in cls.original:
            return method

        # method name
        methodname = method.__func__.__name__

        # class name
        classname = method.im_class.__name__
        try:
            classname = classname_reg.match(classname).group(1)
        except:
            pass

        # wrapper
        @classmethod
        def _xdebug_wrap(*args, **kwds):
            args = args[1:]
            xd = cls.select_instance()
            if method not in xd.enabled:
                xd = cls.get_dummy()
            log_index = len(xd.log)
            back_filename = inspect.currentframe().f_back.f_code.co_filename
            back_lineno = inspect.currentframe().f_back.f_lineno
            xd.log.append("%s-> %s::%s() %s:%d" % ('  '*xd.call_depth, classname, methodname, back_filename, back_lineno))
            start_time = time()
            xd.call_depth += 1
            try:
                return method(*args, **kwds)
            finally:
                running_time = time() - start_time
                xd.log[log_index] = '%.5f ' % (running_time) + xd.log[log_index]
                xd.call_depth -= 1
        cls.original[_xdebug_wrap] = method
        return _xdebug_wrap

    @classmethod
    def instancemethod_wrap(cls, method):
        #if method in cls.original:
        #    return method

        # method name
        methodname = method.__name__
        #if methodname=='_xdebug_wrap':
        #    return method

        # class name
        classname = str(method.im_class)
        try:
            classname = classname_reg.match(classname).group(1)
        except:
            pass

        # wrapper
        def _xdebug_wrap(*args, **kwds):
            xd = cls.select_instance()
            if method not in xd.enabled:
                xd = cls.get_dummy()
            log_index = len(xd.log)
            back_filename = inspect.currentframe().f_back.f_code.co_filename
            back_lineno = inspect.currentframe().f_back.f_lineno
            xd.log.append("%s-> %s::%s() %s:%d" % ('  '*xd.call_depth, classname, methodname, back_filename, back_lineno))
            start_time = time()
            xd.call_depth += 1
            try:
                return method(*args, **kwds)
            finally:
                running_time = time() - start_time
                xd.log[log_index] = '%.5f ' % (running_time) + xd.log[log_index]
                xd.call_depth -= 1
        wrap = types.MethodType(_xdebug_wrap, None, method.im_class)
        cls.original[wrap] = method
        return wrap

    @classmethod
    def function_wrap(cls, func):
        # wrapper
        def _xdebug_wrap(*args, **kwds):
            xd = cls.select_instance()
            xd.log.append("%scall: %s" % ('  '*xd.call_depth, name))
            xd.call_depth += 1
            try:
                return func(*args, **kwds)
            finally:
                xd.call_depth -= 1
        return _xdebug_wrap

 

テストスクリプト

from xdebug import Xdebug

class Fib(object):
    def __init__(self):
        pass

    def calc(self, n):
        if n<3:
            return 1
        return self.calc(n - 1) + self.calc(n - 2)

xd = Xdebug()
xd.enable(Fib)
fib = Fib()
result = xd.run(fib.calc, 6)

print "result: %d\n" % result
print xd.get_result()

 

テストスクリプト実行結果

$ python xtest.py  
result: 8

TIME    METHOD
0.02666 -> __main__.Fib::calc() /tmp/xdebug.py:102
0.01709   -> __main__.Fib::calc() xtest.py:10
0.01004     -> __main__.Fib::calc() xtest.py:10
0.00578       -> __main__.Fib::calc() xtest.py:10
0.00001         -> __main__.Fib::calc() xtest.py:10
0.00001         -> __main__.Fib::calc() xtest.py:10
0.00001       -> __main__.Fib::calc() xtest.py:10
0.00393     -> __main__.Fib::calc() xtest.py:10
0.00001       -> __main__.Fib::calc() xtest.py:10
0.00001       -> __main__.Fib::calc() xtest.py:10
0.00722   -> __main__.Fib::calc() xtest.py:10
0.00405     -> __main__.Fib::calc() xtest.py:10
0.00001       -> __main__.Fib::calc() xtest.py:10
0.00001       -> __main__.Fib::calc() xtest.py:10
0.00001     -> __main__.Fib::calc() xtest.py:10