python - 类中每个方法的标准日志记录

Question

我希望我的脚本中调用的每个类方法都记录完成该方法所花费的时间。在不向每个方法添加日志记录的情况下执行此操作的最佳/最干净的方法是什么？

我可以通过暴力破解来做到这一点，但是向我编写的每个方法添加相同的样板似乎并不正确:

import datetime as dt
import logging
import sys

logger = logging.getLogger()
logging.basicConfig(level=logging.INFO)

class TestA(object):
    def method_one(self):
        begin_at = dt.datetime.utcnow()
        print "Called method_one"
        end_at = dt.datetime.utcnow()
        logger.info('{}.{} took {}'.format(
                __name__,
                sys._getframe().f_code.co_name, # http://code.activestate.com/recipes/66062-determining-current-function-name/
                end_at - begin_at,
            ))

    def method_two(self):
        begin_at = dt.datetime.utcnow()
        print "Called method_two"
        end_at = dt.datetime.utcnow()
        logger.info('{}.{} took {}'.format(
                __name__,
                sys._getframe().f_code.co_name, # http://code.activestate.com/recipes/66062-determining-current-function-name/
                end_at - begin_at,
            ))

class TestB(object):
    def method_three(self):
        begin_at = dt.datetime.utcnow()
        print "Called method_three"
        end_at = dt.datetime.utcnow()
        logger.info('{}.{} took {}'.format(
                __name__,
                sys._getframe().f_code.co_name, # http://code.activestate.com/recipes/66062-determining-current-function-name/
                end_at - begin_at,
            ))

t_a = TestA()
t_b = TestB()

t_a.method_one()
t_a.method_two()
t_a.method_one()
t_b.method_three()

运行它会导致预期的行为:

Called method_one
INFO:test:__main__.method_one took 0:00:00.000172
Called method_two
INFO:test:__main__.method_two took 0:00:00.000006
Called method_one
INFO:test:__main__.method_one took 0:00:00.000005
Called method_three
INFO:test:__main__.method_three took 0:00:00.000005

我想我应该使用装饰器，但我对这些没有经验，我的第一次尝试失败了:

def method_logger(f):
    begin_at = dt.datetime.utcnow()
    output = f()
    end_at = dt.datetime.utcnow()
    logger.info('{}.{} took {}'.format(
        f.__name__,
        sys._getframe().f_code.co_name, # http://code.activestate.com/recipes/66062-determining-current-function-name/
        end_at - begin_at,
    ))
    return output

class TestA(object):
    def method_one(self):
        print "Called method_one"

    def method_two(self):
        print "Called method_two"

class TestB(object):
    def method_three(self):
        print "Called method_three"

我知道我需要以某种方式传递“self”，但不确定如何最好地进行。

Traceback (most recent call last):
  File "test_logging.py", line 68, in <module>
    class TestA(object):
  File "test_logging.py", line 69, in TestA
    @method_logger
  File "test_logging.py", line 59, in method_logger
    output = f()
TypeError: method_one() takes exactly 1 argument (0 given)

如何在不装饰每个方法的情况下复制我的预期行为，我知道怎么做？如果有更好的方法来做我正在做的事情，也请告诉我，我很乐意看到示例。

Answer 1

使用计时函数和装饰器:

def timeit(method):

    def timed(*args, **kw):
        ts = time.time()
        result = method(*args, **kw)
        te = time.time()
        delta = te - ts

        hours, remainder = divmod(delta, 3600)
        minutes, seconds = divmod(remainder, 60)
        logger.info('%s.%s took %02d:%02d:%02.6f',
                     method.__module__,
                     method.__name__,
                     int(hours),
                     int(minutes),
                     seconds)

        return result

    return timed



class TestA(object):

    @timeit
    def method_one(self):
        print "Called method_one"