Logging execution time with decorators

Question

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 a function (during the execution of the function) into a logging file like:

@log_time("log.txt", 35)
def some_function(...):
    ...
    return result

and

from functools import wraps

def log_time(path_to_logfile, interval):
    ...

so that log.txt would look something like

Time elapsed: 0h 0m 35s
Time elapsed: 0h 1m 10s
Time elapsed: 0h 1m 45s

Any ideas?

Answer 1

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