Logging Execution Time With Decorators

After I tried unsuccessfully for a while, I am seeking help from this miraculous website. Now for my problem: I want to create a decorator that writes the elapsed execution time of

Solution 1:

I'll give you the basic overview about what you must do in order to accomplish this. The following is a decorator that accepts two parameters, and executes the function. The missing funcitonality is presented as comments, add them in:

def log_time(path_to_logfile, interval):
    def log(func):
        # 'wrap' this puppy up if needed 
        def wrapped(*args, **kwargs):
            # start timing
            func(*args, **kwargs)
            # stop timing
            with open(path_to_logfile, 'a') as f:
                pass # functionality
        return wrapped
    return log

You can now decorate functions and the output is going to be written in path_to_logfile. So, for example, decorating foo here:

@log_time('foo.txt', 40)
def foo(i, j):
    print(i, j)

foo(1, 2)

Will take foo and execute it. You need to time it appropriately and write the contents to your file. You should experiment with decorators even more and read up on them, a nice article on Decorators exist at the Python Wiki.

Solution 2:

Okay, I figured something out in the end with threads. Thanks for all the suggestions!

import codecs, threading, time
from functools import wraps

def log_time(logpath="log.txt", interval=5):

    def log_time_decorator(func):
        @wraps(func)
        def wrapper(*args, **kwargs):
            t = threading.Thread(target=func, args=args, kwargs=kwargs)
            log_entries = 0
            with codecs.open(logpath, "wb", "utf-8") as logfile:
               start_time = time.time()
               t.start()
               while t.is_alive():
                   elapsed_time = (time.time() - start_time)
                   if elapsed_time > interval * log_entries:
                       m, s = divmod(elapsed_time, 60)
                       h, m = divmod(m, 60)
                       logfile.write("Elapsed time: %2dh %2dm %2ds\n" %(h, m, s))
                       log_entries += 1
        return wrapper
    return log_time_decorator

One disadvantage might be that you cannot easily retrieve the return value of the function (at least I haven't figured it out yet).

EDIT1: Removed an unnecessary variable and added a nice format for logwriting (see this)

EDIT2: Even though other users rejected his edit, I want to include a version from Piotr Dabkowski because it works with a return-value:

def log_time(logpath="log.txt", interval=5):

    def log_time_decorator(func):
        @wraps(func)
        def wrapper(*args, **kwargs):
            RESULT = [None]
            def temp():
                RESULT[0] = func(*args, **kwargs)
            t = threading.Thread(target=temp)
            log_entries = 0
            with codecs.open(logpath, "wb", "utf-8") as logfile:
               start_time = time.time()
               t.start()
               while t.is_alive():
                   elapsed_time = (time.time() - start_time)
                   if elapsed_time > interval * log_entries:
                       m, s = divmod(elapsed_time, 60)
                       h, m = divmod(m, 60)
                       logfile.write("Elapsed time: %2dh %2dm %2ds\n" %(h, m, s))
                       log_entries += 1
            return RESULT[0]
        return wrapper
    return log_time_decorator

Solution 3:

Quickly put together but worked in a test with @timeit on a few functions.

import logging
logging.basicConfig(
    level=logging.DEBUG, 
    filename='myProgramLog.txt', 
    format=' %(asctime)s - %(levelname)s - %(message)s')

import time                                                

def timeit(method):

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

        logging.debug('%r (%r, %r) %2.2f sec' % \
              (method.__name__, args, kw, te-ts))
        return result

    return timed

Sources: https://www.andreas-jung.com/contents/a-python-decorator-for-measuring-the-execution-time-of-methods, https://automatetheboringstuff.com/chapter10/

EDIT: I find Python comes with a pretty good logging module; why re-invent the wheel?