有没有一种在Python中分析线程的好方法？

Question

我是 Python 线程新手。我正在尝试使用 PyGame 制作一个游戏，其中一个占用大量 CPU 的函数获得自己的线程，而另一个函数（获取用户输入并将图形渲染到屏幕上）在线程处于活动状态时在循环中同时运行。

虽然线程几乎按预期工作（它提供了快速的 FPS），但我确实看到帧速率有些波动 - 有些帧只需要几毫秒即可完成，而有些则需要 >200 毫秒。 CPU 密集型线程大约需要 1000 毫秒才能完成。

游戏循环的概要如下（两个函数是

update_world

和

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")

输出日志如下所示（延迟突出显示）：

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

为了找出导致这些跳转的原因，我的第一次尝试是在我的程序上运行 cProfile 以查看哪些调用花费的时间最长。但是，简单的分析不会让您看到哪个调用“锁定”了主线程。有没有一种行之有效的方法可以找到这个问题？

Answer 1

更新

正如评论中指出的，嵌套探查器实际上在 Python 中不起作用。当使用 Python >= 3.12 时，运行下面的代码会引发 ValueError

:

...
    with cProfile.Profile() as pr:
  File "C:\Users\userprofile\anaconda3\envs\py312\Lib\cProfile.py", line 116, in __enter__
    self.enable()
ValueError: Another profiling tool is already active
    self.enable()

答案不正确

一种选择是按照

此处的建议在每个线程中运行单独的分析器。我决定制作一个装饰器 (profile_function

)，它运行探查器并将统计数据转储到一个 

{time.time_ns()}.pstats

 文件，该文件最终可以组合成一个主文件，然后进行分析。

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()