用 eBPF 揪出生产环境隐藏的 N+1 查询：一次从 300ms 到 30ms 的 PostgreSQL 性能抢救

用 eBPF 揪出生产环境隐藏的 N1 查询一次从 300ms 到 30ms 的 PostgreSQL 性能抢救上周值班时有个接口的 P99 延迟突然从 80ms 飙到 300ms。看监控CPU、内存、磁盘 I/O 都正常PostgreSQL 的慢查询日志里甚至没出现这条 SQL。折腾了两个小时我用 eBPF 在内核层抓到了真相——原来是 ORM 隐藏的 N1 查询在搞事情。现象明明没慢查询接口却卡得要死出问题的接口是/api/v1/orders/detail根据订单 ID 返回订单详情连带订单下的商品列表。监控显示应用层 P99 延迟300ms正常 80msPostgreSQL avg query time5ms正常数据库连接池使用率40%不高慢查询日志空这就诡异了。数据库不慢但接口慢。用EXPLAIN ANALYZE跑那条主查询执行计划也正常。我第一反应是网络问题抓了个包用 Wireshark 看TCP 重传也很少。正打算把锅甩给「网络抖动」时运营又在群里反馈用户投诉了。没办法得上点硬核工具了。上 eBPF在内核层看见真相eBPF 这两年很火之前一直没时间在生产环境试。这次正好借机开搞。思路很简单用 eBPF 在内核层追踪 PostgreSQL 的查询执行看看应用到底发了多少条 SQL 到数据库。工具准备我用的bpftrace脚本比 BCC 简洁。Ubuntu 安装sudoapt-getinstallbpftrace追踪脚本写了个简单的 bpftrace 脚本pg_query_trace.bt追踪 PostgreSQL 的查询执行#!/usr/bin/bpftrace #include linux/sched.h BEGIN { printf(Tracing PostgreSQL queries... Hit Ctrl-C to stop.\n); printf(%-10s %-6s %-20s %s\n, TIME(ms), PID, COMM, QUERY_LEN); } // 追踪 PostgreSQL 的 exec_simple_query 函数PostgreSQL 14 uprobe:/usr/lib/postgresql/14/bin/postgres:exec_simple_query { $query str(arg0); $len strlen($query); printf(%-10u %-6d %-20s %d\n, nsecs/1000000, pid, comm, $len); } // 也可以追踪 pg_query 函数获取完整 SQL uprobe:/usr/lib/postgresql/14/bin/postgres:pg_query { $query str(arg0); printf(%s\n, $query); }跑起来sudobpftrace pg_query_trace.bt然后我在另一台机器上用curl连续调用那个慢接口foriin{1..10};docurl-shttps://api.example.com/orders/detail?id$i/dev/null;done发现 N1bpftrace 的输出让我傻眼了Tracing PostgreSQL queries... Hit Ctrl-C to stop. TIME(ms) PID COMM QUERY_LEN ... 1845234 18421 postgres 45 1845235 18421 postgres 52 1845236 18421 postgres 52 1845237 18421 postgres 52 1845238 18421 postgres 52 1845239 18421 postgres 52 1845240 18421 postgres 52 ...一个请求发了几十条 SQL再看具体 SQL 内容我血压上来了SELECT*FROMordersWHEREid12345;SELECT*FROMorder_itemsWHEREorder_id12345;SELECT*FROMproductsWHEREid101;SELECT*FROMproductsWHEREid102;SELECT*FROMproductsWHEREid103;SELECT*FROMproductsWHEREid104;...典型的 N1先查订单再查订单项然后对每个商品 ID 单独发一条查询。根源ORM 的「魔法」变成了「噩梦」看代码后端用的是某 Python ORM不点名了很多 ORM 都有这毛病# views.pyorderOrder.objects.get(idorder_id)itemsorder.items.all()# 这里发了第二条 SQL# 序列化时foriteminitems:productitem.product# 每次循环都发一条 SQL...ORM 的延迟加载lazy loading在开发环境小数据量时没事生产环境一个订单有 20 个商品项就瞬间变成 1 1 20 22 条 SQL。修复两招把 22 条 SQL 压成 2 条第一招select_related prefetch_related把 ORM 查询改成预加载# 修复后orderOrder.objects.select_related().prefetch_related(items__product).get(idorder_id)这样 Django ORM类似的 ORM 都有类似功能会把关联数据一次性 JOIN 或批量查询出来。第二招加一层 Redis 缓存对于订单详情这种读多写少的场景加一层缓存兜底# 带缓存的查询cache_keyforder:{order_id}resultredis.get(cache_key)ifnotresult:orderOrder.objects.select_related().prefetch_related(items__product).get(idorder_id)resultserialize(order)redis.setex(cache_key,300,result)# 缓存5分钟returnresult效果从 300ms 到 30ms修复后重新上线监控数据指标修复前修复后提升P99 延迟300ms30ms10xSQL 查询次数/请求~22 条2 条11x数据库连接池使用40%5%8xCPU 使用率15%3%5x接口响应直接回到 80ms 以内比出问题前还快。写在最后这次排查让我学到两件事第一慢查询日志不是万能的。单条 SQL 执行快不代表请求整体快。N1 的每条查询可能就 5ms但 20 条加起来就是 100ms再加上网络 RTT很容易就突破 300ms。第二eBPF 确实香。不需要改代码、不需要重启服务直接在内核层看见应用和数据库之间的真实交互。以后这种「查不到慢查询但接口慢」的诡异问题我第一反应就是上 eBPF。贴一下完整的追踪脚本需要的朋友自取# pg_n1_detector.bt - 检测 N1 模式的 bpftrace 脚本#!/usr/bin/bpftraceBEGIN{printf(Detecting PostgreSQL N1 patterns...\n);query_count0;start_timensecs;}uprobe:/usr/lib/postgresql/*/bin/postgres:exec_simple_query{query_count;$querystr(arg0);// 检测类似模式的重复查询WHEREid?if(strcontains($query,WHERE id )){id_queries;}}END{$duration(nsecs - start_time)/1000000000;printf(\n--- Summary ---\n);printf(Total queries: %d in %d seconds\n, query_count,$duration);printf(ID lookup queries: %d\n, id_queries);printf(QPS: %d\n, query_count /$duration);if(id_queries5){printf(⚠️ WARNING: Possible N1 detected!\n);}delete(query_count);delete(start_time);delete(id_queries);}eBPF 的可观测性能力还在快速演进内核 5.10 已经支持了很多好用的特性。如果你还没在生产环境试过建议从这种「追踪 SQL」的小场景开始低风险高收益。毕竟能 10 分钟定位的问题何必折腾两个小时呢