Is there a good way to profile threading in Python?

Question

I am new to threading in Python. I am trying to make a game using PyGame where a CPU-heavy function gets its own thread, and where another function (that gets user input and renders graphics to the screen) runs concurrently in a loop while the thread is alive.

While the threading works almost as intended (it gives fast FPS), I do see some choppiness in the framerate - some frames take mere milliseconds to complete, while some take >200ms. The CPU-heavy thread takes around 1000ms to complete.

The outline of the game loop is as follows (the two functions are update_world and input_output):

def update_world():
    # lots of CPU heavy stuff

def input_output():
    # read user input, and display the game to the screen

def run():
    exit_flag = False
    while not exit_flag:
        LOGGER.info("Start of loop")
        LOGGER.info("Create update_world thread")
        t = Thread(target=update_world)
        LOGGER.info("Start update_world thread")
        t.start()
        LOGGER.info("Loop while thread is alive")
        while t.is_alive():
            LOGGER.info("Start input/output routine")
            exit_flag = input_output()
        LOGGER.info("End of loop")

The output log looks as follows (delay highlighted):

2023-07-06 09:20:30,375 - run - INFO - Start of loop
2023-07-06 09:20:30,376 - run - INFO - Create update_world thread
2023-07-06 09:20:30,376 - run - INFO - Start update_world thread
2023-07-06 09:20:30,376 - run - INFO - Loop while thread is alive
2023-07-06 09:20:30,376 - run - INFO - Start input/output routine
2023-07-06 09:20:30,382 - run - INFO - Start input/output routine
2023-07-06 09:20:30,389 - run - INFO - Start input/output routine
2023-07-06 09:20:30,699 - run - INFO - Start input/output routine <-- here we see a jump of >200ms
2023-07-06 09:20:30,751 - run - INFO - Start input/output routine
2023-07-06 09:20:30,759 - run - INFO - Start input/output routine
2023-07-06 09:20:30,766 - run - INFO - Start input/output routine
2023-07-06 09:20:30,773 - run - INFO - Start input/output routine
2023-07-06 09:20:30,780 - run - INFO - Start input/output routine
2023-07-06 09:20:30,789 - run - INFO - Start input/output routine
2023-07-06 09:20:30,798 - run - INFO - Start input/output routine
2023-07-06 09:20:30,805 - run - INFO - Start input/output routine
2023-07-06 09:20:30,813 - run - INFO - Start input/output routine
2023-07-06 09:20:30,821 - run - INFO - Start input/output routine
2023-07-06 09:20:30,828 - run - INFO - Start input/output routine
2023-07-06 09:20:30,855 - run - INFO - Start input/output routine
2023-07-06 09:20:30,863 - run - INFO - Start input/output routine
2023-07-06 09:20:30,872 - run - INFO - Start input/output routine
2023-07-06 09:20:30,878 - run - INFO - Start input/output routine
2023-07-06 09:20:30,886 - run - INFO - Start input/output routine
2023-07-06 09:20:30,895 - run - INFO - Start input/output routine
2023-07-06 09:20:30,903 - run - INFO - Start input/output routine
2023-07-06 09:20:30,914 - run - INFO - Start input/output routine
2023-07-06 09:20:30,922 - run - INFO - Start input/output routine
2023-07-06 09:20:30,932 - run - INFO - Start input/output routine
2023-07-06 09:20:30,975 - run - INFO - Start input/output routine
2023-07-06 09:20:30,990 - run - INFO - Start input/output routine
2023-07-06 09:20:31,005 - run - INFO - Start input/output routine
2023-07-06 09:20:31,025 - run - INFO - Start input/output routine
2023-07-06 09:20:31,043 - run - INFO - Start input/output routine
2023-07-06 09:20:31,071 - run - INFO - Start input/output routine
2023-07-06 09:20:31,080 - run - INFO - Start input/output routine
2023-07-06 09:20:31,092 - run - INFO - Start input/output routine
2023-07-06 09:20:31,101 - run - INFO - Start input/output routine
2023-07-06 09:20:31,108 - run - INFO - Start input/output routine
2023-07-06 09:20:31,118 - run - INFO - Start input/output routine
2023-07-06 09:20:31,126 - run - INFO - Start input/output routine
2023-07-06 09:20:31,219 - run - INFO - Start input/output routine <-- another jump
2023-07-06 09:20:31,273 - run - INFO - End of loop

In order to figure out what causes these jumps, my first attempt was to run cProfile on my program to see which calls take the longest. However, simple profiling won't let you see which calls "lock" the main thread. Is there a tried-and-true way of finding this out?

Threads are not meant for CPU-heavy functions, if you want something for that, use `multiprocessing`. Threading's use cases would be I/O bound stuff, because threading doesn't run in parallel, they share the process, i.e., one thread acquires GIL, runs for a bit, then another thread acquires GIL, runs for a bit and so they rotate around like so and sleepier threads becomes even slower in the end. — Matiiss, Jul 06 '23 at 09:28

score 0 · Answer 1 · answered Jul 06 '23 at 08:50

One option is to run a separate profiler in each thread as suggested here. I decided to make a decorator (profile_function) that runs the profiler and dumps the stats to a {time.time_ns()}.pstats file that can be combined into one master file in the end and then analyzed.

import logging
from threading import Thread
import time

import cProfile
import pstats
import glob

LOGGER = logging.getLogger()

def profile_function(func):
    def inner(*args, **kwargs):
        with cProfile.Profile() as pr:
            ret = func(*args, **kwargs)
        pr.dump_stats("{}.pstats".format(time.time_ns()))
        return ret
    return inner

@profile_function
def update_world():
    for i in range(5):
        print(i)
        time.sleep(1)

@profile_function
def input_output():
    return bool(input("userinput"))

@profile_function
def run():
    exit_flag = False
    while not exit_flag:
        LOGGER.info("Start of loop")
        LOGGER.info("Create update_world thread")
        t = Thread(target=update_world)
        LOGGER.info("Start update_world thread")
        t.start()
        LOGGER.info("Loop while thread is alive")
        while t.is_alive():
            LOGGER.info("Start input/output routine")
            exit_flag = input_output()
        LOGGER.info("End of loop")

run()
filenames = glob.glob("*.pstats")
stats = pstats.Stats(*filenames)
stats.dump_stats("combines_stats")
stats.print_stats()

Is there a good way to profile threading in Python?

1 Answers1