In this piece we will see how to measure thread execution time in a multithreaded python program.

Problem

Let’s start with an anecdote — I was working on a python project and it had lot of legacy code (libraries/methods for handling different tasks), this application spawns lot of threads for many IO bound tasks and the time it takes to complete these tasks depends on various variable factors like the platform application runs on, network latency, API response time, disk IO etc. We observed that the time taken for application to run was quite random and as we scaled and supported multiple platforms we started seeing more time drifts. Though we already knew the factors causing these time drifts but it was essential for us to quantify the time taken by application(piece by piece), so that we can identify the poor performing parts of code. To accomplish this, we had to have the data of all different pieces of the program. As we knew, major chunk of the application were these ‘n’ no. of threads application instantiate for performing various IO bound tasks hence to tune application performance we need the the numbers. In this post, i will share ‘decorator’ based approach which can be utilized to measure the thread execution time your programs.

---

We will simplify this problem so that we can understand it with an example, below is an example(simpler version) of similar problem, a python program which spawns 10 worker threads to perform some tasks. We will use python’s time.sleep() method to add random delay to our workers as an input to simulate real world example. We will also measure program’s overall execution time(do checkout timeit module approach as well on measure program’s execution time).

import threading
import time

# Capture program start time
start_time = time.perf_counter()

thread_pool = list()                  # container to hold threads
total_delay = 0
# container with random int (5, 20)
delay_index = [8, 15, 18, 12, 19, 7, 14, 8, 16, 16]
# A worker method
def worker(delay: int) -> None:
    # Doing something
    time.sleep(delay)
    print(f"Worker_{delay} took {delay} secs to complete")
# Create worker threads and add them to thread_pool
for i in range(len(delay_index)):
    _delay = delay_index[i]
    total_delay += _delay
    t = threading.Thread(target=worker,, args(_delay,),name=f'Worker_{_delay}'))
    thread_pool.append(t)
# start worker threads
for _thread in thread_pool:
    _thread.start()             
    print(f'--- Started {_thread.name}')
# join the threads
for _thread in thread_pool:
    _thread.join()               
    print(f'--- Completed {_thread.name}')
    print(f'{_thread.name} took {_thread.thread_duration} secs ')
    duration_from_decorator += _thread.thread_duration
# Capture program execution time
end_time = time.perf_counter()
execution_time = end_time - start_time
# print stats
print(f'Total execution time: {execution_time} secs')
print(f'Total no of threads: {len(thread_pool)}')
print(f'Average total time: {execution_time / len(thread_pool)}')

Above was our sample program, let‘s’ unpack what is happening:

• worker: This method will simulates program’s IO bound tasks, it will complete the task after delay secs (_delay__ is an input to the worker method)._
• delay_index : I have used random.randint(5, 20) to generate random integers, this would be the input to worker method (we will use same input later as well).
• Then we instantiated 10 worker thread objects using **threading **module, we assigned worker method to target and then appended instantiated thread objects thread_pool list.
• Later we used thread_pool to get thread objects, we start them and wait till they are done.
• You’ll notice, we are also measuring program execution_time along with some print statements.

Now, lets run the program and check the output below:

• You’ll notice we have ran the program 3 times (Run-1, Run-2, Run-3) with same input to worker method i.e. delay_index = [8, 15, 18, 12, 19, 7, 14, 8, 16, 16].
• Note that theAverage time for each thread comes around ~ 1.900 secs. We use following formula to calculate Average time (total execution time / no of threads).
• Total time program takes to run is around ~19.00 secs despite using multihreading and thats because we have delay of 19 secs at delay_index[4].

# Run-1
Total execution time: 19.004492659 secs
Total no of threads: 10
Average time: 1.9004492659
# Run-2
Total execution time: 19.005527918000002 secs
Total no of threads: 10
Average time: 1.9005527918000003
# Run-3
Total execution time: 19.004814707 secs
Total no of threads: 10
Average time: 1.9004814707000002

#threading #time #multithreading #measure-time #python