Standard logging for every method in a Class

Question

I would like every class method that is called in my script to log the time it took to complete the method. What is the best/cleanest way to do this without adding logging to every method?

I can do this by brute-forcing it, but adding the same boilerplate to every method I write doesn't seem right:

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

Running this results in the intended behavior:

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

I think I should be using decorators, but I'm inexperienced at these, and my first attempt fell flat:

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"

I get that I need to pass 'self' in somehow, but am not sure how best to proceed.

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)

How can I replicate my intended behavior without decorating every single method, the way I know how? Please also let me know if there's a better way to do what I'm doing, would love to see examples.

Is this of any help http://stackoverflow.com/questions/6307761/how-can-i-decorate-all-functions-of-a-class-without-typing-it-over-and-over-for — Bahrom, Jul 11 '16 at 19:49
You don't appear to be actually decorating your methods when using a decorator ... a quick [google search](https://www.google.com/?ion=1&espv=2#q=python%20decorators) revealed [this guide](https://realpython.com/blog/python/primer-on-python-decorators/#real-world-examples) which has a walkthrough for your exact problem. — Hamms, Jul 11 '16 at 19:49
Are you sure you don't just want to use the Python profiler instead? https://docs.python.org/2/library/profile.html (it/they are very easy to use..) — thebjorn, Jul 11 '16 at 19:57

score 1 · Accepted Answer · answered Jul 11 '16 at 21:04

Use a timing function and a decorator:

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"

Not quite, as I'd like to avoid putting `@timeit` in front of every method. — selwyth, Jul 12 '16 at 23:37
This is the most elegant way to do it. You cannot expect that something that is not written will be run. — Or B, Jul 13 '16 at 04:17

Standard logging for every method in a Class

1 Answers1