"点了导出以后,就登录不上了。"
这是现场的普遍反馈。系统是公司内部的充电桩建站管理系统,Django 写的。那天闪充在赶进度,用系统的人特别多。以前也卡,但用户能忍;那天人一多,直接登录不上了。
我第一反应是网络问题,或者服务器宕机了。重启服务,恢复了。回头翻日志才发现,服务没挂,就是单纯的卡。
vibe coding 的顽疾
这个系统是多人一起 vibe coding 写出来的,其中几个人编码经验一般。我感觉这就是 vibe coding 的顽疾:每个人让 AI 把自己的功能跑通就提交,没人看查询次数,很容易出现大面积性能低下的代码。
上半年没有像样的监控。有人反馈卡,我就问他做了什么操作之后变慢的,去翻日志找共同点,再让 AI 逐段看相关代码。这个阶段找到最多的是 N+1 查询:先查一个列表,再对列表里每条记录单独查一次关联数据。12 条记录就是 13 次数据库访问,改成批量是 2 次。物料导入、结算列表、领料导出陆续改成批量读写,有一次 3,508 行的导入从 41 秒降到 0.5 秒。
但 N+1 修了一批,卡还是卡。最头疼的就是这个阶段:监控不全,看哪里都像病因。AI 也只能无头分析,一会儿说是 Python 的问题,一会儿说是架构的问题。我自己心里其实一直 100% 认定是 Excel 导出卡住的,因为反馈里总是"点了导出以后"。
一道保护,一个新问题
后来出过一次整机宕机。云服务器厂商的监控上能看到,那个时间点 CPU 和内存一起飙上去,直指阻塞和竞争。8 月 17 日又出了一次数据库连接耗尽。
第二天我在 ASGI 层加了一个并发限制,同一时刻最多放 80 个请求进 Django:
class ConcurrencyLimitMiddleware:
def __init__(self, app, max_concurrency: int):
self.app = app
self.semaphore = asyncio.Semaphore(max_concurrency)
async def __call__(self, scope, receive, send):
if scope["type"] != "http":
return await self.app(scope, receive, send)
async with self.semaphore:
return await self.app(scope, receive, send)
数据库是保住了。但 80 个位置要是被几个慢请求长期占着,后面所有请求都得排队,包括登录。这一点当时我没想清楚,是后来 trace 告诉我的。
trace 里的元凶和受害者
8 月起陆续接了 Prometheus、Grafana、Loki、Tempo。9 月给并发中间件补了两个数:一个请求等槽位等了多久(queue_wait),拿到槽位后占了多久(slot_hold)。
9 月 17 日下午又报了一次无响应。16:38 到 16:40 这两分钟里,80 个槽位全满,排队的请求最多 53 个,全站 P95 6.39 秒。从 Tempo 里把这段时间的 trace 拆开,请求分成了两类。
一类是拿到槽位后执行很久的:
接口 queue_wait slot_hold 其中
project-measure/submit 0 66.882s DB 48 个 span 合计 0.694s
dashboard/key-progress/overview 0 47.636s DB 27.707s,单条 SQL 27.235s
quality-control/flow-module-status 0 19.696s DB 54 个 span 合计 2.681s
protected/media 0 18.393s S3 HEAD 0.915s
另一类是根本没拿到槽位、一直在等的:
接口 queue_wait slot_hold
projects/status-list 15.841s 5.027s
patrol/statistics 18.555s 3.298s
project-measure/item-data/save 4.197s 5.975s
项目状态列表那条请求总耗时 20.9 秒。只看总耗时,它是最像元凶的那个,实际上它四分之三的时间在排队,是被拖累的。真正占着位置不放的是第一张表里那几个。
最离谱的是计量提交:占了槽位 66.9 秒,数据库只花了 0.7 秒。剩下 66 秒在干什么?看代码,它在一个同步 HTTP 请求里依次做了标准值生成、Excel 生成、加水印、文件保护。关键节点进度总览则是缓存没命中时全量查项目和进度数据,projects_project 上一条 SQL 跑了 27 秒。
看到这两张表,我第一感觉是终于找到原因了。紧接着发现,原因不止一个。我一直认定的 Excel 导出确实是一部分,但还有慢 SQL、同步检查文件存储、全量计算。它们成因不同,得分开治。
分开治
按接口隔离槽位。 给媒体、状态列表、计量提交这类接口单独分配槽位,其余请求共用公共槽位。某一类堵住了,不会把所有位置占满。现在公共槽位 40 个,独立槽位合计 124 个。排队设了等待上限,超时直接返回"服务繁忙"。调高槽位只能让更多请求进来,不会让慢请求变快。
耗时任务挪到后台。 9 月引入 Celery,Excel 导出、ZIP 打包、加水印这类活交给独立的 Worker。用户提交导出,系统立刻回"已受理",任务完成后去任务中心下载。第一批改了 51 种导出,10 月项目 Excel 导入也改了。前提是先把缓存从各进程内存迁到 Redis,不然后台算好的东西网页服务读不到。
这一步不是加一行 .delay() 那么简单。任务登记了但消息没发出去、重试导致文件重复生成、进程中途退出、别人能不能下载你的文件,这些都得处理,所以又补了 Outbox 投递、幂等、超时恢复和受控下载。后来还发现,长导出能把 Worker 全占满,报表刷新这种短任务排到过期,跟网页服务的槽位问题一模一样。10 月 14 日把定时任务拆到了单独的 Worker。
报表提前算。 报表访问频繁、计算量大,大多能接受几分钟延迟。改成后台每 2 到 5 分钟算一次写进 Redis,用户打开页面直接读。多个请求同时发现缓存过期时只让一个去算(singleflight),刷新失败就保留上一次的结果。
查询本身做减法。 后台和缓存替代不了查询优化,导出挪到后台,烂查询照样吃数据库。10 月集中改了几处:省市进度报表改成数据库分组统计,结算和计量列表改成数据库分页、只为当前页加载明细,补了几个组合索引。每处都配了回归测试,校验新旧结果一致,并且限制查询次数,防止数据量涨上去又冒出 N+1。
动手之前我还会先问一句:这项统计、这个全量返回,业务上真的需要吗?不需要的直接砍,比优化它省事。
中间也考虑过升级 Python 去掉 GIL,最后没做。3.13 的无 GIL 是可选构建,依赖也有兼容问题。更重要的是,上面两张表里没有一个慢是 GIL 造成的。
效果
后台任务平台 10 月 13 日上线。我挑了上线前后各一个周一,10 月 12 日和 10 月 26 日,09:00 到 18:00,数据来自生产 Prometheus。
| 指标 | 10 月 12 日 | 10 月 26 日 |
|---|---|---|
| P95 耗时 | 2.285 秒 | 0.389 秒 |
| P99 耗时 | 13.689 秒 | 0.966 秒 |
| 超过 5 秒的比例 | 2.606% | 0.095% |
| 排队数峰值 | 153 | 0 |
| 登录 P95 | 13.2 秒 | 0.46 秒 |
| 结算管理列表 P95 | 26.9 秒 | 1.60 秒 |
登录的请求量两天差不多,都是四千次左右,P95 从 13.2 秒降到 0.46 秒。
这组数字要打折扣。上线后那天请求总量少了约 36%,这是线上观测,不是同等负载的压测。同期 SQL 改写、缓存预热、Worker 隔离是一起上的,分不清各自贡献多少。导出改成异步以后,HTTP 返回只代表任务受理了,不代表文件生成得更快。
还没做的
现在排查的方式变了:先定窗口和基准,让 AI 按接口把告警、日志、trace 收上来,分给多个 Agent 并行查,业务上的取舍我来定,改完再回监控验证。有了 queue_wait 和 slot_hold,AI 不会再一会儿说 Python 一会儿说架构了。
还没做的:
- 压测。系统到底能扛多少请求,现在没有数据。
- 后台任务的完成耗时。上线前没这个指标,导出到底是不是变快了,没法比。
- 剩下的导入接口还没接后台任务。
- 几个定时报表会在同一时刻刷新,要错开。
- 团队还在 vibe coding。N+1 靠回归测试里的查询次数断言兜着,能兜多久,不知道。