写技术博客到第九周这一周没有按原计划去写一个新功能的实现而是被线上一个突发的性能问题打断了节奏。这个问题很有意思一个平时只有80毫秒的订单查询接口某天下午突然飙升到7秒CPU和内存看着都没打满数据库连接数也正常但页面上就是转圈圈。排查过程用了py-spy、memory-profiler、MySQL慢查询日志这一整套链路最后发现根因藏在一个很不起眼的索引缺失里。这篇博客就完整记录这次排查过程包括每个工具在什么阶段用、看什么数据、怎么解读结果以及最后总结出来的一套通用提速思路。不管你是做后端开发、Python服务运维还是刚接触性能调优不久这周的内容应该都能给你一些参考。1. 现象是第一现场先把慢接口的“体感”量化出来几乎所有的性能问题一开始都是“感觉变慢了”但感觉不靠谱。这次收到用户反馈后我做的第一件事不是去看代码而是先确认接口到底慢在哪。1.1 从监控大盘区分瓶颈维度我先打开了监控面板看了这个接口的调用量、P99耗时、CPU使用率、内存占用、磁盘IO和网络IO这几组数据。当时的观察结果是接口P99从80ms涨到7秒调用量并没有明显变化CPU使用率在25%到35%之间浮动没有出现打满的情况内存占用比平时高了约500MB但还没有触发OOM磁盘IO和网络IO都算平稳这个组合很关键。如果CPU打满那通常是计算密集或者死循环如果内存接近上限可能是泄漏或大对象如果IO很高那是数据读写有问题。现在哪一项都不算极端所以要先怀疑“链路中的某个环节存在阻塞性等待”——也就是有东西在等而不是在算。当时我把可能的原因分成了四类可能方向判断依据优先级CPU/计算热点CPU未打满但不是完全排除中锁等待或线程阻塞接口耗时高而CPU低典型特征高数据库慢查询连接数正常不代表SQL不慢高下游服务或网络IO阻塞网络IO不高但需确认下游耗时中这四类方向就是后面的排查索引。我习惯把这个步骤叫作“给现场拍一张照片”先别动任何代码把现象用数据固定下来否则后面很容易被某个假线索带偏。1.2 发布变更与时间线的对账还有一个不能漏的环节确认这个接口是不是在最近一次发布后才变慢的。我核对了一下最近的发布记录发现这个接口涉及的服务在过去三天内有两次更新但变更内容都集中在订单状态的推送逻辑上看起来和查询链路关系不大。和同事确认过回滚方案可行之后我先按兵不动继续往深挖。如果一上来就回滚万一不是版本问题反而浪费时间。这里也补充一个经验遇到性能问题首先要问“时间点”如果慢查询出现在一次发布之后那git diff通常比任何profiling工具都能更快定位问题。但如果接口没有发布也在变慢那就老老实实做数据采集。2. 用py-spy给运行中的Python进程做一次“无痕体检”确认了是个链路级问题之后我决定先看Python进程内部到底卡在哪。这里没有用cProfile原因很简单cProfile是基于trace钩子实现的会让线上服务的执行速度下降10到20倍这种开销在生产环境根本扛不住。我选了py-spy。2.1 py-spy的工作原理与优势py-spy是一个基于采样的Python程序剖析工具。它不修改字节码也不需要给代码加装饰器而是直接读取进程的运行时信息周期性抓取当前调用栈再通过统计栈顶采样次数来估算热点函数。这个机制的重点在于采样是“旁观者”视角不在Python解释器内部埋点所以对原进程的性能影响非常小。官方给的数据是开销大概在1%到5%的量级实际用下来高峰期中低负载接口上基本无感。它和cProfile的差别可以这样理解cProfile像让每个人在工作时都拿小本子记一笔做完再汇总py-spy则像一个每天定时来巡查的HR只记你在干什么不需要你自报。后者在线上是真正能用的方案。2.2 实际采集过程中的三条命令我这次用了三个子命令分别完成不同的任务# 1. 动态查看进程内各线程的当前调用栈 py-spy dump --pid 进程PID # 2. 以top模式实时刷新线程CPU占用与热点函数 py-spy top --pid 进程PID # 3. 持续采集60秒导出火焰图分析耗时分布 py-spy record --pid 进程PID -o profile.svg --duration 60第一步我先用dump看看进程在瞬间的状态这个命令会输出进程内每个线程的Python栈能够快速发现线程是不是卡在同一个位置。第二步的top模式能动态刷新各个线程的CPU占用和当前执行函数。前两步找到可疑方向后再用record做一次60秒的采样生成火焰图来分析整体耗时分布。我这边的执行过程是先dump了一次看到线程都集中在/order/list相关的函数上然后开着top观察了约30秒确认不是瞬时状态最后record了60秒SVG文件打开后火焰图显示压倒性的耗时集中在json.loads和OrderSnapshot.to_dict这两个函数上占比接近65%。2.3 容器环境里容易踩的权限坑这里值得单独记录一个坑我的服务跑在Docker容器里使用py-spy attach到容器进程时直接报了一个权限错误。原因是py-spy在Linux上通过process_vm_readv或perf_event_open读取进程信息容器默认的seccomp或capability配置会拦截这类操作。解决办法是在docker-compose或docker run时给容器添加SYS_PTRACE能力services: orders-service: build: . cap_add: - SYS_PTRACE加上之后重启容器再执行py-spy命令就正常了。需要提醒的是SYS_PTRACE算是一个高权限的capability生产环境建议在排查窗口临时开启排查完再收回去不要长期挂着。另外高版本Docker如果还报错检查一下seccomp:unconfined是否被安全策略禁止优先用cap_add方案。2.4 火焰图告诉我们数据准备环节有问题拿到火焰图后我并没有急着去看json.loads这个函数本身而是顺着调用链看了一下它上层的函数关系。普通的性能优化思路会想“json解析慢那换orjson”但这只是治标。火焰图的真实信息是/order/list接口在“准备数据”阶段把大量的订单快照字段从JSON字符串重新解析成了Python对象然后每解析一个还要再执行一次dict转换。逻辑上这个操作应该是业务处理完快照之后生成一次就好但火焰图显示它在同一个请求里重复执行了很多次。这说明代码里可能存在循环重复解析同一个快照、或者把JSON字符串当临时状态反复传递的情况。到了这一步疑点已经从“数据库慢”转向了“内存里的数据处理异常”。于是我把下一个工具换成了memory-profiler。3. memory-profiler顺藤摸瓜内存数据处理的异常放大py-spy告诉我们“json.loads是热点”但“为什么热点在这里”需要通过内存视角来进一步确认。memory-profiler是一个按行统计函数内存占用的工具它能精确地告诉你每一行代码执行完后新增了多少内存、持有多少内存。我用它在灰度环境里复现了一次请求先做全量内存曲线观察。3.1 用mprof看整体内存曲线安装之后我用了它的时间序列模式# 后台执行被监控的程序输出曲线数据 mprof run --interval 0.1 --output memory.dat python ./order_list_bench.py # 作图 mprof plot memory.dat -o memory_usage.png执行结果里内存占用的曲线呈现明显的“锯齿状”每个请求进来内存就涨一大截请求结束又回落。这类锯齿本身是正常的GC释放对象就会有回落。但问题在于锯齿的底部在慢慢抬高也就是基线内存从1.1GB爬到了1.4GB左右持续几十个请求后并没有完全回到原样——这是典型的“某些对象被长期持有不释放或者列表反复扩容导致内存碎片化”的信号。这里补充一个判断技巧锯齿回落但底部不回到原位才叫内存泄漏的早期特征如果锯齿能完全回到起点那只是峰值高不算泄漏。之前有段时间我一看到内存曲线有锯齿就以为泄漏了后来才发现判断标准应该是基线不是峰值。3.2 按行profile定位到大对象复制曲线定位到方向后我给有嫌疑的处理函数加上了profile装饰器再单独运行一次请求输出按行内存明细from memory_profiler import profile profile def build_order_response(snapshot): raw_data snapshot.json_content # 占用约 800 MB orders_list json.loads(raw_data) # 又新增约 900 MB clean_orders [strip_empty_fields(order) for order in orders_list] # 再新增约 400 MB return clean_orders输出结果显示json.loads(raw_data)这一行在解析时内存一次性增加了约900MB。这个体量远超过订单列表本身应该占用的空间——唯一的解释是snapshot.json_content里的JSON字符串里塞了大量冗余字段。继续往下查发现是订单快照保存时把整条商品描述、物流轨迹、甚至部分用户画像都序列化了而查询列表时只需要其中几个字段。这种设计在初期没问题但快照数量一多每次查询都会把所有字段解析一遍内存和CPU被白白烧掉。这里又叠加了一个浅拷贝的隐患部分代码用了clean_orders orders_list[:]这种写法原以为复制了一份实际只是复制了引用列表底层对象还是共享的导致GC无法回收大对象。3.3 内存工具的不适合场景与使用窗口需要说清楚memory-profiler是侵入式的profile装饰器会让被监控函数运行速度明显下降。所以这类工具不适合在生产高峰直接上我一般会在灰度环境或低峰期使用。如果你连灰度环境都没有至少先看mprof的整体曲线再决定要不要按行profile。通过这一轮内存分析基本可以确认接口慢不是单一原因而是“大JSON反复解析 内存对象持续累积 数据库取数低效”三个因素叠加的结果。SQL层的验证下一步水到渠成。4. 根因直击慢SQL与索引缺失才是最后的底牌如果说py-spy和memory-profiler解决的是“进程内发生了什么”那慢SQL日志和explain解决的就是“数据从哪里来、来得多费劲”。我习惯把SQL层的排查放在内存排查之后可以避免被进程内的假热点误导。4.1 开启慢查询日志并抓取现场我先在MySQL实例上临时开启了慢查询记录-- 可以动态打开不需要重启实例 SET GLOBAL slow_query_log ON; SET GLOBAL long_query_time 1;注意long_query_time单位是秒这里设置成1秒是为了把7秒的查询抓出来。设置完成后让流量再走几分钟然后查看慢日志mysqld --verbose --help | grep -i slow-query-log-file # 或直接查变量 SHOW VARIABLES LIKE slow_query_log_file;从慢日志里我很快看到一条SQL执行时间约6.8秒来源正是订单列表页。这条SQL关联了五张表其中核心的是order_items表扫描行数rows_examined达到300万行最终只返回20行。典型的高代价低选择性查询。4.2 explain执行计划里的三个危险信号拿到慢SQL后我在这条SQL前面加上EXPLAIN重新执行EXPLAIN SELECT o.id, o.order_no, u.nickname, oi.sku_id, oi.quantity, oi.price FROM orders o LEFT JOIN users u ON u.id o.buyer_id LEFT JOIN order_items oi ON oi.order_id o.id LEFT JOIN skus s ON s.id oi.sku_id LEFT JOIN promotions p ON p.id oi.promotion_id WHERE o.buyer_id 123456 AND o.status 1 ORDER BY o.create_time DESC LIMIT 20;执行计划的结果里重点看这几列列名看到的值含义typeALL全表扫描没有走索引keyNULL没有命中的索引rows约300万预估扫描行数ExtraUsing temporary; Using filesort使用临时表排序内存压力大三个信号叠在一起基本可以断定order_items表在order_id字段上没有索引。orders表本身有PRIMARY KEY查询条件也能定位到80个订单但order_items表要通过order_id关联没有索引就只能逐行扫描300万行扫下来6.8秒一点也不冤。4.3 联合索引的落地与验证问题定位清楚后添加索引就很简单了ALTER TABLE order_items ADD INDEX idx_order_sku_create (order_id, sku_id, create_time);为什么选择这个组合因为order_id是关联条件最常以等值条件出现在WHERE或JOIN中必须放在最左侧sku_id用来在订单内过滤商品维度create_time用在后边的排序场景。MySQL索引本质是B树结构最左前缀规则决定了一个联合索引能被哪些查询用到。顺序设计的原则是等值条件列放在前面范围或排序列放后面。如果一开始就放create_time而没有order_id这个索引对这个查询基本没用。执行完毕后再次EXPLAINtype变成了refrows从300万降到了约40Extra里不再出现Using temporary和Using filesort。接口响应从6.8秒降到了120毫秒左右优化效果非常直接。4.4 收尾的缓存层与需要避开的坑到了这一步其实问题已经解决了。但我又做了一层优化把热门的订单列表接口加上了一层Redis缓存热点数据直接从缓存读接口P99降到了30毫秒。缓存不是无脑加需要注意以下情况缓存键要带版本号避免发布后读取到旧数据建议设置合理的过期时间并加上随机偏移防止缓存雪崩商品价格、库存这类高频更新数据要谨慎缓存避免读到脏数据穿透场景要有空值缓存或布隆过滤器防止恶意请求直接打到数据库这次的业务场景是订单快照属于只读型数据缓存策略相对简单。如果换成价格计算这种强一致场景不要为了性能牺牲正确性。5. 一套可以复制的性能问题排查顺序这次排查看起来工具用了一堆实际上核心逻辑只有一条先确定瓶颈维度再做进程内采样最后落到数据库执行计划。我把它整理成一个可以直接照做的顺序清单。阶段看什么常用工具关注指标1. 现象量化监控大盘的耗时、CPU、内存、IO自建监控/Prometheus/GrafanaP99、CPU、内存基线、IO2. 时间线核对最近发布变更git log、CI/CD记录变更前后耗时对比3. 进程内热点Python调用栈采样py-spy火焰图中的占比函数4. 内存分析大对象与GC情况memory-profiler/mprof基线是否回落、大对象占用5. 数据库层慢日志与执行计划MySQL slow_log EXPLAINtype、key、rows、Extra这套顺序不是我发明的是长期调优形成的习惯。核心原则是先看数据不要猜先按维度排除不要一上来就优化代码。很多人在第一步就跳过了直接盯着代码里某个函数说“这里应该优化”结果优化半天发现瓶颈在数据库。5.1 几个从这次实战中总结出的编码建议这次问题有三个代码层面的诱因顺便记录下来希望你写代码时能避开第一个是做数据快照时不要无脑塞大字段。订单快照里有商品描述、物流轨迹、用户画像但列表页根本不需要。建议快照表只保留展示需要的字段大字段单独存或者直接拆分表。第二个是典型的大JSON反复解析问题。如果一段JSON字符串在一个请求里要json.loads两次以上就要检查数据流是不是绕了圈子。更推荐在写入时就拆好字段或使用jsonpath按需读取而不是整包解析。第三个是浅拷贝的误用。list_a[:]看起来像是复制了一个新列表实际上对于列表里的对象仍然是共享引用。如果后续持有新列表但修改了对象属性原列表里的对象同样会被修改。对于内存来说浅拷贝并不会帮你释放底层对象的空间。5.2 不同压力场景下的工具选择这次用的py-spy、memory-profiler各有自己的适用场景。在流量低、可以接受侵入的测试环境cProfile和memory-profiler是够用的在线上高压力场景py-spy是首选。如果问题出在GIL竞争py-spy的火焰图同样能观察到大量线程在等待GIL。如果在Windows环境下调试py-spy同样支持但权限问题比Linux更严格需要以管理员身份运行。低版本Linux内核如果无法使用perf相关的采样py-spy会退回/proc解析模式采集开销会略高需要观察一下是否影响在线服务。6. 排查之外这次“第九周”让我记下的几条体会这周没有按原计划写新功能反而觉得收获比写代码更大。要补充的是最后几点实际的心里话第一排查性能问题时时间线信息永远是第一优先级。一个服务变慢先看发布、再SQL慢日志、然后才是profiling。我在py-spy上花了比较多的时间最后才发现核心是SQL索引如果能更快核对时间线我本可以跳过一大半的分析工作。这不是说py-spy没用而是说工具要按顺序用才能把效率拉满。第二采样型工具和侵入型工具要分场景。py-spy我只在线上高峰期用过它基本无感。memory-profiler存在明确的性能副作用我在灰度环境里用了可以接受线上直接加profile会被监控告警误伤。第三一个隐藏的细节慢查询日志要设置合理的阈值。默认long_query_time10会漏掉大量1秒到10秒的慢SQL建议日常就调到1秒如果数据量大可以先按天存储再定期清理。第四这次修复后我没有立刻把观察窗口关掉。索引和缓存上线后我持续看了两天确认内存基线回落到1.1GB以下P99稳定在30ms后再收尾。性能问题优化完不等于结束复测观察和量化对比才是闭环。第五写博客也有点像做隔离排查——先记录现象再记录工具输出最后写结论。过段时间再看这份记录也是给自己备了一份排查手册。