loca1h0st's Blog
loca1h0st's Blog

一次完整的生产环境性能问题排查与优化过程

一次完整的生产环境性能问题排查与优化过程

事件描述及上下文

当前环境后端接口打开极慢(>10s),给出环境上下文信息:

  • Python 版本:3.12.3
  • 框架:FastAPI + uvicorn
  • 运行模式:异步 (asyncio + anyio)
  • 数据库:MongoDB (motor 异步驱动)
  • 状态:生产环境,长期运行,非压测状态

当前服务器状态

第一反应检查CPU和内存,但检查发现CPU运行稳定,第一眼看上去没到危险值

这里被自己的第一直觉坑到了,请记住这个是一个双核 CPU 的 vps

https://blog.mrtblogs.net/wp-content/uploads/2025/12/image-1.avif

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

https://blog.mrtblogs.net/wp-content/uploads/2025/12/image-3-1024x949.avif

基础信息获取

基础架构上看不出啥,就只能从应用层上找点信息了,尝试用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一切正常:

https://blog.mrtblogs.net/wp-content/uploads/2025/12/image-5-1024x428.avif

发表回复

textsms
account_circle
email

loca1h0st's Blog

一次完整的生产环境性能问题排查与优化过程
事件描述及上下文 当前环境后端接口打开极慢(>10s),给出环境上下文信息: Python 版本:3.12.3 框架:FastAPI + uvicorn 运行模式:异步 (asyncio + anyio) 数据库:M…
扫描二维码继续阅读
2025-12-26