笔者最近在参与 LLM 推理框架 PD 分离相关工作, 在完成开发压测过程中发现一个很奇怪的点: 有一些请求会在被放入 asyncio.Queue 之后要 1 秒钟左右之后才会被 Queue 消费端可见. 这让我感到有些意思, 于是准备进入深入分析一番. 首先我要有一个趁手的工具, 最起码可以展示这 1 秒内各个线程都在做什么.
当然首推的就是 py-spy 了, 但 py-spy 有个问题, 其支持的 record 采样输出格式中没有一个会带有采样堆栈对应的时间戳. 所以第一步是为 py-spy 增加一种输出格式, 支持记录并输出采样得来的堆栈以及堆栈被采样时的时间戳. P.S. 才发现 py-spy 居然是用我最爱的 Rust 开发!
之后开始尝试使用 py-spy 进行采样, 但发现 py-spy record -g 的功能有些奇怪: -g Only include traces that are holding on to the GIL.
# /tmp/1.py
import threading
import time
lock = threading.Lock()
def thread_function(name):
with lock:
while True:
print(f"Thread {name} has acquired the lock")
time.sleep(0.1)
thread1 = threading.Thread(target=thread_function, args=(1,))
thread2 = threading.Thread(target=thread_function, args=(2,))
thread1.start()
thread2.start()
thread1.join()
thread2.join()
zhanyi@hidva.com:~$ nohup python /tmp/1.py 1>/dev/null 2>&1 &
[1] 1638442
zhanyi@hidva.com:~$ time py-spy record -p 1638442 -o 1638442.pyspy.record -f raw -g -t -i -n -r 10
py-spy> Sampling process 10 times a second. Press Control-C to exit.
^C
py-spy> Stopped sampling because Control-C pressed
py-spy> Wrote raw flamegraph data to '1638442.pyspy.record'. Samples: 0 Errors: 0
py-spy> You can use the flamegraph.pl script from https://github.com/brendangregg/flamegraph to generate a SVG
real 0m9.965s
user 0m0.010s
sys 0m0.012s
理论上 py-spy 至少应该采样 9 * 10 条样本, 但实际上 py-spy 一条样本都没有采样到. 继续翻了下 py-spy 代码才发现:
let gil_thread_id = if interp.gil_locked().unwrap_or(true) {
get_gil_threadid::<I, Process>(self.threadstate_address, &self.process)?
} else {
0
};
let mut traces = Vec::new();
let mut threads = interp.head();
while !threads.is_null() {
// Get the stack trace of the python thread
let thread = self
.process
.copy_pointer(threads)
.context("Failed to copy PyThreadState")?;
threads = thread.next();
let python_thread_id = thread.thread_id();
let owns_gil = python_thread_id == gil_thread_id;
if self.config.gil_only && !owns_gil {
continue;
}
也即在当前没有任何线程持有着 GIL 时, py-spy 拿到的 gil_thread_id 为 0, 这导致了 owns_gil 总是 false, 此时 py-spy 跳过了对所有线程的采样. 而这可就不符合我的期望了: 若在采样时发现有线程持有着 GIL, 那就只采样这个线程对应的堆栈, 这样一方面不会缺失有效信息, 另一方面也避免对其他线程进行采样影响了效率. 若在采样时发现没有任何线程持有着 GIL, 则需要对所有线程进行采样, 此时各个线程的堆栈都是对排查有帮助的重要信息. 于是再次对 py-spy 进行了改动使 -g 具有我期望的操作.
在工具完善之后, 在我抓到那 1 秒钟各个线程的堆栈之后, 结论就很清晰了. 这些信息就与具体的业务相关了, 对读者参考意义不会很大, 这里就不多提了, 只记录下结论:
