Elegant Python solution for tracking/logging elapsed time?

Question

With the goal of capturing meaningful elapsed-time information in for logs, I have replicated the following time-capture and logging code across many functions:

import time
import datetime

def elapsed_str(seconds):
    """ Returns elapsed number of seconds in format '(elapsed HH:MM:SS)' """
    return "({} elapsed)".format(str(datetime.timedelta(seconds=int(seconds))))

def big_job(job_obj):
    """ Do a big job and return the result """
    start = time.time()
    logging.info(f"Starting big '{job_obj.name}' job...")
    logging.info(f"Doing stuff related to '{job_type}'...")
    time.sleep(10)  # Do some stuff...
    logging.info(f"Big '{job_obj.name}' job completed! "
                 f"{elapsed_str(time.time() - start)}")
    return my_result

With sample usage output:

big_job("sheep-counting")
# Log Output:
#   2019-09-04 01:10:48,027 - INFO - Starting big 'sheep-counting' job...
#   2019-09-04 01:10:48,092 - INFO - Doing stuff related to 'sheep-counting'
#   2019-09-04 01:10:58,802 - INFO - Big 'sheep-counting' job completed! (0:00:10 elapsed)

I'm looking for an elegant (pythonic) method to remove these redundant lines from having to be rewritten each time:

1. start = time.time() - Should just automatically capture the start time at function launch.
2. time.time() - start Should use previously captured start time and infer current time from now(). (Ideally elapsed_str() would be callable with zero arguments.)

My specific use case is to generate large datasets in the data science / data engineering field. Runtimes could be anywhere from seconds to days, and it is critical that (1) logs are easily searchable (for the word "elapsed" in this case) and (2) that the developer cost of adding the logs is very low (since we don't know ahead of time which jobs may be slow and we may not be able to modify source code once we identify a performance problem).

Answer 1

The recommended way is to use time.perf_counter() and time.perf_counter_ns() since 3.7.

In order to measure runtime of functions it is comfortable to use a decorator. For example the following one:

import time

def benchmark(fn):
    def _timing(*a, **kw):
        st = time.perf_counter()
        r = fn(*a, **kw)
        print(f"{fn.__name__} execution: {time.perf_counter() - st} seconds")
        return r

    return _timing

@benchmark
def your_test():
    print("IN")
    time.sleep(1)
    print("OUT")

your_test()

(c) The code of this decorator is slightly modified from sosw package