A python decorator that logs execution time.

LICENSE.txt

Copyright 2020 Brad Montgomery

Permission is hereby granted, free of charge, to any person obtaining a copy of this software 
and associated documentation files (the "Software"), to deal in the Software without restriction, 
including without limitation the rights to use, copy, modify, merge, publish, distribute, sublicense, 
and/or sell copies of the Software, and to permit persons to whom the Software is furnished to do so, 
subject to the following conditions:

The above copyright notice and this permission notice shall be included in all copies or substantial 
portions of the Software.

THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT 
LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN 
NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, 
WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE 
SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.

timer.py

"""
A simple execution time logger implemented as a python decorator.

Available under the terms of the MIT license.
"""

import logging
import time

from functools import wraps

logger = logging.getLogger(__name__)


# Misc logger setup so a debug log statement gets printed on stdout.
logger.setLevel("DEBUG")
handler = logging.StreamHandler()
log_format = "%(asctime)s %(levelname)s -- %(message)s"
formatter = logging.Formatter(log_format)
handler.setFormatter(formatter)
logger.addHandler(handler)


def timed(func):
    """This decorator prints the execution time for the decorated function."""

    @wraps(func)
    def wrapper(*args, **kwargs):
        start = time.time()
        result = func(*args, **kwargs)
        end = time.time()
        logger.debug("{} ran in {}s".format(func.__name__, round(end - start, 2)))
        return result

    return wrapper


@timed
def slow_function():
    """This is a slow-running function used as an example."""
    print("running a slow function...", end="")
    time.sleep(3.2)
    print("done")


if __name__ == "__main__":
    slow_function()

hi,
where code logs execution time? when ı run your code there is no execution time in my output.

@ayvazc: you probably need to set your loggers level to debug first, otherwise the actuall log record will be discarded. One way to do so: add after line 4:
logger.setLevel('DEBUG')
Though in your full program, that should probably be done elsewhere.

Missing import time

😅 things that happen when you copy/paste from other sources... Updated this gist to include a working example.

What's the license for this? I'm tired writing these things each time from scratch.

@matanster

What's the license for this? I'm tired writing these things each time from scratch.

I just added a license; it's MIT, feel free to use this in your projects.

Here's my own, which I ended up using again. It's not a decorator though, but it caters for more scenarios. I added fn.__name__ from you, to my old code. Thanks again for sharing.

def timed(fn, *args, human_fn_description=None, warning_threshold=None, always=False, **kwargs):
    """  executes a function while timing its elapsed time, and logging it according to the supplied parameters """

    if not human_fn_description:
        human_fn_description = fn.__name__

    now = time.time()
    result = fn(*args, **kwargs)
    duration = time.time() - now

    if warning_threshold is None:
        if always:
            logging.info(f'{human_fn_description} took {duration:.3f} seconds')

    elif duration > warning_threshold:
        logging.warning(f'{human_fn_description} took {duration:.3f} seconds')

    return result, duration

I have written a modified one: https://gist.github.com/saif-mahmud/793735279ebd367ea1855470c5bdd33f

Example Usage:

def func(a, b):
    time.sleep(1.5)
    return a + b, a - b


t_log = TimeLogger()

for i in range(1, 10):
    res = t_log.timed(func, i, i + 5, description='Operation on Integers', verbose=True)
    # print(res)

t_log.summary()

Output:

2021-02-08 13:24:59.953 INFO -- [Operation on Integers] Elapsed Time : 1.50175 sec
2021-02-08 13:25:01.455 INFO -- [Operation on Integers] Elapsed Time : 1.50173 sec
2021-02-08 13:25:02.957 INFO -- [Operation on Integers] Elapsed Time : 1.50161 sec
2021-02-08 13:25:04.459 INFO -- [Operation on Integers] Elapsed Time : 1.50173 sec
2021-02-08 13:25:05.961 INFO -- [Operation on Integers] Elapsed Time : 1.50175 sec
2021-02-08 13:25:07.462 INFO -- [Operation on Integers] Elapsed Time : 1.50171 sec
2021-02-08 13:25:08.965 INFO -- [Operation on Integers] Elapsed Time : 1.50175 sec
2021-02-08 13:25:10.467 INFO -- [Operation on Integers] Elapsed Time : 1.50174 sec
2021-02-08 13:25:11.969 INFO -- [Operation on Integers] Elapsed Time : 1.5016 sec
[Operation on Integers] Avg. Elapsed Time : 1.50171 sec