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

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"

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

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"