事件描述及上下文
当前环境后端接口打开极慢(>10s),给出环境上下文信息:
- Python 版本:3.12.3
- 框架:FastAPI + uvicorn
- 运行模式:异步 (asyncio + anyio)
- 数据库:MongoDB (motor 异步驱动)
- 状态:生产环境,长期运行,非压测状态
当前服务器状态
第一反应检查CPU和内存,但检查发现CPU运行稳定,第一眼看上去没到危险值
这里被自己的第一直觉坑到了,请记住这个是一个双核 CPU 的 vps

服务器监控信息显示CPU占用才一半,同期内存占用数据较为健康,虽然没配置SWAP,但内存没有到危险值,且真触发OOM应该是业务不可用:

基础信息获取
基础架构上看不出啥,就只能从应用层上找点信息了,尝试用htop/top命令看看稳定的50%的CPU占用从哪来的
System load: 1.34 Temperature: 19.9 C
top - 11:16:55 up 15 days, 12:18, 10 users, load average: 1.38, 1.29, 1.17
Tasks: 151 total, 2 running, 149 sleeping, 0 stopped, 0 zombie
%Cpu(s): 50.8 us, 1.6 sy, 0.0 ni, 47.6 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
MiB Mem : 7397.3 total, 1881.4 free, 3616.1 used, 2191.1 buff/cache
MiB Swap: 0.0 total, 0.0 free, 0.0 used. 3781.2 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2865374 root 20 0 4332932 930540 22912 R 101.6 12.3 34,58 uvicorn
3079230 root 20 0 1260640 108572 14464 S 1.6 1.4 11:08.71 python3
1900 nginx 20 0 1742988 370084 10624 S 0.8 4.9 32:25.26 mysqld
1926 nginx 20 0 39368 4352 1664 S 0.8 0.1 90:46.38 redis-server
1981 nginx 20 0 149360 6784 2816 S 0.8 0.1 43:20.20 redis-server
2279207 nginx 20 0 4795804 998124 49152 S 0.8 13.2 28:30.49 mongod
2279247 root 20 0 1745184 5760 3072 S 0.8 0.1 1:25.83 docker-proxy
1 root 20 0 22560 10684 6600 S 0.0 0.1 0:56.12 systemd
可以看到 PID 为 2865374 的 uvicorn 进程吃了100% 的CPU,load average: 1.38, 1.29, 1.17,与监控的稳定的50%左右的CPU占用能匹配上,看起来是这个进程导致的单进程单核打满服务了。
考虑这个服务实际运行了一个 FastAPI 的Web服务,大概率猜测应该是代码里面死循环或者忙抢占不到CPU的资源,或者是同步阻塞了。具体是什么原因,只能继续往下进行排查,用 top -H -p 2865374 查具体的线程的信息:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2865374 root 20 0 4327812 925532 22912 R 99.7 12.2 33,59 uvicorn
2865444 root 20 0 4327812 925532 22912 S 0.7 12.2 12:02.85 uvicorn
2865443 root 20 0 4327812 925532 22912 S 0.3 12.2 13:45.78 uvicorn
2865422 root 20 0 4327812 925532 22912 S 0.0 12.2 0:00.00 JS Helper
2865423 root 20 0 4327812 925532 22912 S 0.0 12.2 0:00.00 JS Helper
2865424 root 20 0 4327812 925532 22912 S 0.0 12.2 0:00.00 JS Helper
2865441 root 20 0 4327812 925532 22912 S 0.0 12.2 0:00.09 uvicorn
从上面的信息可以明显的看到,第一个线程吃了99.7%的CPU,其余的基本为0。那就基本可以得出结论是代码上死循环或者CPU密集任务导致的抢不到资源后的CPU空占用。
经过观察,考虑测试环境没有这个问题,最方便的方式就是在生产环境上dump一个堆栈下来进行排查,如果复杂就要dump火焰图来看了。
考虑是生产环境,在venv环境里面安装了py-spy然后把进程的信息dump出来(敏感资源和非重要堆栈已经删除):
Collecting samples from '/***/***/.venv/bin/python /***/***/.venv/bin/uvicorn app.main:app' (python v3.12.3)
Total Samples 1009
GIL: 100.00%, Active: 500.00%, Threads: 23
%Own %Total OwnTime TotalTime Function (filename)
255.56% 255.56% 22.04s 22.11s _worker (concurrent/futures/thread.py)
66.67% 100.00% 4.37s 6.50s _run (pymongo/periodic_executor.py)
55.56% 66.67% 3.81s 5.95s _deliver_cancellation (anyio/_backends/_asyncio.py)
33.33% 33.33% 2.13s 2.13s recv_into (pymongo/network_layer.py)
33.33% 33.33% 1.95s 1.95s _run_safe_shutdown_loop (pycares/__init__.py)
33.33% 100.00% 1.27s 8.35s _run_once (asyncio/base_events.py)
11.11% 11.11% 1.07s 1.75s _call_soon (asyncio/base_events.py)
...
Press Control-C to quit, or ? for help.
(venv) root@***:~# py-spy dump -p 2865374
Process 2865374: /***/***/.venv/bin/python /***/***/.venv/bin/uvicorn app.main:app
Python v3.12.3 (/usr/bin/python3.12)
Thread 2865374 (active+gil): "MainThread"
_deliver_cancellation (anyio/_backends/_asyncio.py:574)
...
__call__ (click/core.py:1442)
<module> (uvicorn:10)
Thread 2865442 (idle): "ThreadPoolExecutor-2_0"
_worker (concurrent/futures/thread.py:89)
run (threading.py:1010)
_bootstrap_inner (threading.py:1073)
_bootstrap (threading.py:1030)
Thread 2865443 (idle): "pymongo_server_monitor_thread"
recv_into (pymongo/network_layer.py:469)
...
_bootstrap_inner (threading.py:1073)
_bootstrap (threading.py:1030)
Thread 2865444 (idle): "pymongo_kill_cursors_thread"
_run (pymongo/periodic_executor.py:252)
run (threading.py:1010)
_bootstrap_inner (threading.py:1073)
_bootstrap (threading.py:1030)
Thread 2865446 (idle): "pymongo_server_rtt_thread"
_run (pymongo/periodic_executor.py:252)
run (threading.py:1010)
_bootstrap_inner (threading.py:1073)
_bootstrap (threading.py:1030)
Thread 2865449 (idle): "asyncio_0"
_worker (concurrent/futures/thread.py:89)
run (threading.py:1010)
_bootstrap_inner (threading.py:1073)
_bootstrap (threading.py:1030)
Thread 2866061 (idle): "ThreadPoolExecutor-2_1"
以下是一堆 ThreadPoolExecutor 和 asyncio 的 idle
从上面的报错信息上来看就非常清楚了,23个线程一直在抢占GIL,堆栈打出来的信息里面没有任何的业务代码的存在,全是ThreadPoolExecutor和pymongo,但pymongo理论上不会导致100%的CPU,代码内的使用也是标准的异步方式,pymongo/periodic_executor.py 这个可能是因为GIL抢占不到的等待导致的雪崩效应。到这一步就能确定去找业务代码里面的线程设计使用/轮询的相关代码问题了。
最后的核心问题:
# app/***/***.py:***
async def get_leader_data(leader_address: str):
client = get_***_client()
user_state = await asyncio.to_thread(client.get_user_state, leader_address)
在以上的代码中,get_***_client()是引用的外部SDK,这里面是一个同步的HTTP的请求,但在下一步被送入了一个异步的线程池中,所有的线程会被阻塞的调用http的请求,逻辑如下(AI是最好的解释老师):
时间轴:
t=0s: 启动同步任务
├─ Leader1-10: asyncio.to_thread(get_user_state)
└─ 10 个任务同时提交到线程池
t=0.001s: 线程池状态(最多 12 个工作线程)
Thread-0 到 Thread-9 ← 正在执行 HTTP 请求(阻塞中)
⚠️ 10 个线程都在等待外部 API 响应
⚠️ 这些线程虽然在"等待",但仍然占用系统资源
t=1s: 所有 HTTP 请求返回
↓ 10 个线程同时唤醒,准备返回结果
↓ 开始争抢 GIL(Global Interpreter Lock)
Thread-0: [等待 GIL] ← CPU 自旋等待
Thread-1: [等待 GIL] ← CPU 自旋等待
...
Thread-9: [等待 GIL] ← CPU 自旋等待
⚠️ 10 个线程都在"自旋"等待获取 GIL
⚠️ 这就是 CPU 100% 的根本原因
为什么会 CPU 50%?
Python 的 GIL 特性:
- 同一时刻只有一个线程可以执行 Python 字节码
- I/O 操作(如 HTTP 请求)会释放 GIL
- 但返回结果时需要重新获取 GIL
- 多个线程同时竞争 GIL 时,会导致 CPU 自旋等待
实际影响:
- 理论上 10 个请求并发执行,1 秒完成
- 实际上因为 GIL 争抢,需要 3-5 秒
- CPU 占用 100%,但实际工作效率很低
但为什么应该是100%的CPU占用监控只显示了50%?这就提到上面的坑了,这是一台2核的服务器,考虑Web应用并不是一个CPU密集型的,启动的命令中没有显示指定workers的数量,默认为1来跑..这就变成了,单核的100%,在监控上显示50%…
最后,修复了bug之后的监控显示CPU一切正常:

发表回复