一次 API 延迟问题的排查：从网络波动到事件循环阻塞

为什么一个正常只需要 20ms 的 API 调用，偶尔会卡 10 秒甚至更久？本文记录一次真实的排查过程，最终发现问题出在事件循环阻塞。

🎯 问题现象

某天，我们发现一个 HTTP API 调用出现了诡异的延迟问题：

更奇怪的是：

• 不是所有请求都慢，大部分请求正常
• 慢的请求没有明显规律，无法预测
• 同一个用户，上一个请求正常，下一个就可能卡住

这种"偶发性"问题最难排查——无法复现，无法预测。

---

🔍 假设一：响应体太大导致传输慢

推理

最直观的想法：响应数据量大 → 下载时间长 → 延迟高

正常请求: [请求] ──20ms──> [响应 50KB]
异常请求: [请求] ──5000ms──> [响应 500KB] ?

如果慢的请求都是因为响应体大，那问题就简单了——优化响应大小即可。

验证

收集了一批请求的数据，对比响应大小与延迟的关系：

关键发现：

• 响应大小差异仅 6%
• 但延迟差异达到 190 倍
• 更反直觉的是：响应最大的请求（600+ KB）反而不是最慢的

结论

❌ 假设不成立。响应大小与延迟没有正相关关系。

---

🔍 假设二：网络波动

推理

既然不是数据量的问题，那可能是网络抖动：

• 某些时刻网络拥塞
• 导致 TCP 传输慢
• 或者 DNS 解析卡住

正常时: [客户端] ──10ms──> [服务端]
抖动时: [客户端] ──5000ms──> [服务端]

验证

写了一个独立的测试脚本，直接请求目标服务：

import aiohttp
import asyncio
import time

async def test_network():
    async with aiohttp.ClientSession() as session:
        for i in range(100):
            start = time.perf_counter()
            async with session.get("https://target-service/health") as resp:
                await resp.text()
            elapsed = (time.perf_counter() - start) * 1000
            print(f"Request {i}: {elapsed:.1f}ms")
            await asyncio.sleep(0.1)

asyncio.run(test_network())

运行结果：

Request 0: 12.3ms
Request 1: 11.8ms
Request 2: 13.1ms
Request 3: 12.5ms
...
Request 99: 11.9ms

100 次请求，全部稳定在 10-15ms，没有任何异常。

结论

❌ 假设不成立。网络本身没有问题。

---

🔍 假设三：代码问题——事件循环阻塞

推理

网络没问题，但请求就是慢。问题必然出在本地代码。

项目使用 FastAPI + asyncio，突然想到一个关键点：

asyncio 是单线程的，如果事件循环被阻塞，所有并发请求都会排队等待。

┌────────────────────────────────────────────────────────────┐
│                   单线程事件循环                            │
│                                                            │
│  请求 A ──┐                                                │
│  请求 B ──┼──→ [事件循环] ──→ 逐个执行                      │
│  请求 C ──┘                                                │
└────────────────────────────────────────────────────────────┘

如果某个请求的处理函数中包含同步阻塞代码：

1. 该请求会"霸占"事件循环
2. 其他请求全部排队等待
3. 等待的请求感知到的就是"延迟"

验证方向

1. 检查代码中是否有同步阻塞调用
2. 检查第三方库是否真正支持异步
3. 检查是否有 CPU 密集型操作

可能的元凶

审查代码后，发现了几个可疑点：

# 可疑点 1：某个第三方 SDK 的调用
result = third_party_sdk.process(data)  # 同步？异步？

# 可疑点 2：JSON 序列化大对象
json.dumps(huge_dict)  # CPU 密集

# 可疑点 3：某些日志操作
logger.info(f"Data: {large_object}")  # 字符串格式化

结论

✅ 高度可疑。需要进一步验证具体是哪个调用导致了阻塞。

---

🎓 原理讲解：为什么事件循环阻塞会导致延迟

asyncio 的工作模型

Python 的 asyncio 采用单线程 + 协作式多任务模型：

┌────────────────────────────────────────────────────────────┐
│                    事件循环 (Event Loop)                    │
│                                                            │
│   本质上就是一个 while True 循环：                          │
│                                                            │
│   while True:                                              │
│       task = get_next_ready_task()                         │
│       task.run_until_await()  # 执行直到遇到 await         │
│       check_io_completions()                               │
│                                                            │
│   关键：整个循环在 **单线程** 里运行                        │
└────────────────────────────────────────────────────────────┘

await 是什么？

await 是协程"让出控制权"的关键字：

async def handler():
    # 1. 发起网络请求
    response = await http_client.get(url)
    # 2. await 时，协程暂停，事件循环去执行其他任务
    # 3. 网络请求完成后，事件循环恢复这个协程
    return response

图解：

时间轴 ────────────────────────────────────────────────────────────►

         ┌─────────┐
协程 A:  │  运行   │ await ─────────────────┐  ┌─────────┐
         └─────────┘                        │  │ 继续运行 │
                    ↓ 让出控制权             │  └─────────┘
                                            ↓ I/O 完成，恢复
                   ┌─────────┐
协程 B:            │  运行   │ await ────────┐
                   └─────────┘               │
                              ↓ 让出控制权    ↓
                   
                             ┌─────────┐
协程 C:                      │  运行   │ ...
                             └─────────┘

多个协程可以"交替"执行，实现并发。

同步代码为什么阻塞？

同步代码没有 await 点，不会让出控制权：

async def bad_handler():
    result = requests.get(url)  # 同步！没有 await！
    return result

图解：

时间轴 ────────────────────────────────────────────────────────────►

         ┌────────────────────────────────────────────────────────┐
协程 A:  │        requests.get(url) - 卡住了，出不来！              │
         └────────────────────────────────────────────────────────┘
         
         ×××××××××××××××××××××××××××××××××××××××××××××××××××××××××
协程 B:                     等待中...无法执行
         ×××××××××××××××××××××××××××××××××××××××××××××××××××××××××
         
         ×××××××××××××××××××××××××××××××××××××××××××××××××××××××××
协程 C:                     等待中...无法执行
         ×××××××××××××××××××××××××××××××××××××××××××××××××××××××××

requests.get() 执行期间，整个事件循环停转，其他所有请求都在排队。

累积效应

假设每个请求有 100ms 的同步阻塞：

时间轴 ────────────────────────────────────────────────────────────►

请求 A: [阻塞 100ms]
请求 B:              [等 100ms][阻塞 100ms]
请求 C:                                    [等 200ms][阻塞 100ms]
请求 D:                                                          [等 300ms]...

→ 请求 D 的感知延迟 = 300ms+，但实际网络请求只需要 20ms！

这就解释了为什么延迟是"随机"的——取决于你的请求前面排了多少个阻塞请求。

---

🚨 常见的"隐藏阻塞"场景

很多阻塞代码看起来很正常，但实际上会卡住事件循环：

1. 同步 HTTP 客户端

# ❌ 错误：requests 是同步的
import requests
response = requests.get(url)

# ✅ 正确：使用 aiohttp 或 httpx
import aiohttp
async with aiohttp.ClientSession() as session:
    async with session.get(url) as response:
        data = await response.json()

2. 同步睡眠

# ❌ 错误：time.sleep 会阻塞整个事件循环
import time
time.sleep(1)

# ✅ 正确：使用 asyncio.sleep
import asyncio
await asyncio.sleep(1)

3. CPU 密集型操作

# ❌ 可能有问题：大量计算占用事件循环
result = hashlib.pbkdf2_hmac('sha256', password, salt, 100000)  # 可能 100ms+

# ✅ 正确：放到线程池执行
import asyncio
loop = asyncio.get_event_loop()
result = await loop.run_in_executor(None, compute_hash, password, salt)

4. 同步数据库驱动

# ❌ 错误：psycopg2 是同步的
import psycopg2
conn = psycopg2.connect(...)
cursor.execute("SELECT ...")

# ✅ 正确：使用 asyncpg
import asyncpg
conn = await asyncpg.connect(...)
await conn.fetch("SELECT ...")

5. 文件 I/O

# ❌ 可能有问题：同步文件读取
with open("large_file.txt") as f:
    data = f.read()

# ✅ 正确：使用 aiofiles
import aiofiles
async with aiofiles.open("large_file.txt") as f:
    data = await f.read()

6. 第三方 SDK

# ⚠️ 需要检查：第三方 SDK 是否支持异步？
result = third_party_sdk.process(data)

# 如果不支持，包装到线程池
result = await loop.run_in_executor(None, third_party_sdk.process, data)

---

🛠️ 实用技巧：用健康检查检测事件循环阻塞

一个简单但有效的方法：利用 /health 端点检测事件循环是否被阻塞。

原理

健康检查端点通常非常简单，正常情况下应该在 1-5ms 内返回。但如果事件循环被阻塞，/health 请求也会排队等待：

时间轴 ────────────────────────────────────────────────────────────►

业务请求:  [同步阻塞 3000ms............................]
                                                      ↑
/health:   [排队等待 3000ms..........................]  [1ms]
                                                      
→ /health 响应时间暴露了阻塞！

实现

在健康检查端点中添加事件循环延迟检测：

import asyncio
import logging
import time

from fastapi import APIRouter

router = APIRouter()
logger = logging.getLogger(__name__)


@router.get("/healthz")
async def healthz() -> dict:
    """健康检查端点，同时检测事件循环是否有阻塞"""
    # 测量事件循环的响应能力
    start = time.perf_counter()
    await asyncio.sleep(0)  # 让出控制权，立即恢复
    loop_latency_ms = (time.perf_counter() - start) * 1000

    if loop_latency_ms > 50:
        logger.warning(f"[EventLoop] degraded, latency={loop_latency_ms:.2f}ms")
    else:
        logger.debug(f"[EventLoop] healthy, latency={loop_latency_ms:.2f}ms")

    return {}

关键点

1. await asyncio.sleep(0)：让出控制权并立即恢复，测量事件循环的响应速度
2. 正常情况：延迟应该 < 1ms
3. 有阻塞时：延迟会接近阻塞时长

日志示例

# 正常
DEBUG - [EventLoop] healthy, latency=0.05ms

# 有阻塞
WARNING - [EventLoop] degraded, latency=523.45ms

在日志系统中搜索 [EventLoop] degraded 就能发现所有阻塞事件，配合时间戳可以定位问题。

---

✅ 解决方案

通用原则

在 async 函数中，任何可能耗时的操作都应该用 await：

包装同步代码到线程池

如果某个库不支持异步，可以用 run_in_executor 包装：

import asyncio
from concurrent.futures import ThreadPoolExecutor

# 创建线程池
executor = ThreadPoolExecutor(max_workers=10)

async def safe_sync_call(sync_func, *args, **kwargs):
    """安全地执行同步函数，不阻塞事件循环"""
    loop = asyncio.get_event_loop()
    return await loop.run_in_executor(
        executor, 
        lambda: sync_func(*args, **kwargs)
    )

# 使用
result = await safe_sync_call(third_party_sdk.process, data)

检查清单

部署前检查：

• 所有 HTTP 调用使用异步客户端（aiohttp, httpx）
• 没有 time.sleep()，改用 asyncio.sleep()
• 数据库使用异步驱动（asyncpg, aiomysql）
• CPU 密集操作放到线程池
• 第三方 SDK 确认是否异步，不支持则包装

---

📊 排查流程总结

┌─────────────────────────────────────────────────────────────────┐
│                       问题排查流程                               │
│                                                                 │
│  1. 收集数据，量化问题                                           │
│     └─ 慢请求占比？延迟分布？                                    │
│                                                                 │
│  2. 假设：响应体太大？                                           │
│     └─ 对比大小 vs 延迟 → 不相关 → 排除                          │
│                                                                 │
│  3. 假设：网络波动？                                             │
│     └─ 独立脚本测试 → 稳定 → 排除                                │
│                                                                 │
│  4. 假设：事件循环阻塞？                                         │
│     └─ 代码审查 + 计时日志 → 发现阻塞点 → 确认                   │
│                                                                 │
│  5. 修复：替换同步调用 / 包装到线程池                            │
│                                                                 │
└─────────────────────────────────────────────────────────────────┘

---

🎯 核心教训

一句话总结

在异步框架中，一个同步阻塞就可能拖垮整个服务。

三个关键认知

1. asyncio 是单线程的

   • 所有协程共享一个线程
   • 阻塞一个就阻塞全部

2. await 是协作的关键

   • 只有遇到 await，协程才会让出控制权
   • 同步代码不会让出，会"霸占"事件循环

3. 偶发性延迟往往是阻塞的信号

   • 延迟取决于前面排了多少阻塞请求
   • 表现为随机、不可预测

一个比喻

把事件循环想象成一个单车道收费站：

• 正常情况：每辆车（协程）快速通过
• 异步 await：车停下说"我等 ETC 响应，你先走"
• 同步阻塞：车直接停在车道上翻找现金，后面全堵住

---

📚 延伸阅读

• Python asyncio 官方文档
• FastAPI 并发与 async/await
• aiohttp 官方文档
• Understanding Python GIL

---

🚀 总结

这次排查经历让我深刻理解了 asyncio 的工作原理：

异步编程的本质是"协作"——每个协程都要遵守规则，快进快出，把时间让给别人。任何不遵守规则的代码，都会破坏整体性能。

下次遇到偶发性延迟问题时，不妨先问自己：有没有同步代码混进了异步函数？

---

你的项目中有类似的"隐藏阻塞"吗？欢迎分享你的排查经历。