python

《Python编程实战》16.1 剖析方法论

回到最前线的性能工作：用标准库 cProfile + pstats 贴出真实 cumtime/tottime 排序，用 pyinstrument 5.1.3 看采样调用树，用 timeit 做微基准、用 sys.monitoring 做轻量追踪，讲清如何读火焰图，并把「先测量再优化」立成本书的纪律。

Leeting Yan 8 分钟阅读 3569 字

本节目标：建立「先测量再优化」的纪律——用 cProfile + pstats 做确定性剖析，用 pyinstrument 5.1.3 看采样调用树，用 timeit 做微基准、用 sys.monitoring 做轻量追踪，并读懂火焰图，把「优化」从直觉变成证据。
适用版本：Python 3.12+（实测 3.14.6）；pyinstrument 5.1.3

16.1 剖析方法论

第 15 章把应用交付了出去，接下来要回答一个更难的问题：它够快吗？哪里慢？ 大多数人凭直觉猜瓶颈，结果往往优化了错的 5%，放过了真正的 80%。这一节只做一件事：把「哪里慢」变成可测量、可复现的证据。

16.1.1 先测量再优化：三条纪律

在动手前先立三条纪律，它们比任何工具都重要：

  1. 不测量不优化。没有 profiling 数据就动手改代码，等于闭着眼睛调参。经验上「我觉得慢的地方」和「真的慢的地方」重合率低得惊人。
  2. 优化要有基线。改之前先记下「耗时 / 内存」的原始数字，改完再测一次，用比值说话，而不是「感觉快了」。
  3. 一次只改一个变量。同时改五处，就算快了也不知道是哪处起了作用；只有单变量对照，结论才能复用。

下面用一个「报告生成」负载贯穿全节。它做三件事：解析 CSV 文本、清洗名字、汇总金额：

# workload.py
import json
import re

def parse_records(raw: str) -> list[dict]:
    out = []
    for line in raw.splitlines():
        if not line.strip():
            continue
        parts = line.split(",")
        out.append({"id": int(parts[0]), "name": parts[1], "amount": float(parts[2])})
    return out

def normalize_names(records: list[dict]) -> list[dict]:
    for r in records:
        r["name"] = re.sub(r"[^a-zA-Z0-9 ]", "", r["name"]).strip().title()
    return records

def summarize(records: list[dict]) -> dict:
    total = 0.0
    for r in records:
        total += r["amount"]
    return {"count": len(records), "total": round(total, 2)}

def build_report(raw: str) -> str:
    records = parse_records(raw)
    records = normalize_names(records)
    return json.dumps(summarize(records))

if __name__ == "__main__":
    raw = "\n".join(f"{i},User-{i}!!,{i * 1.5}" for i in range(200_000))
    print(build_report(raw)[:60])

直觉上「解析 CSV」像大头，summarize 里的加法循环也像；但直觉对不对，得测了才知道。

16.1.2 cProfile + pstats：确定性剖析

cProfile 是标准库自带的确定性剖析器：它给每个函数调用埋点，精确记录调用次数与耗时。确定性的代价是开销不小（通常数倍于正常运行），但数字精确、粒度到函数，是「定位热点」的第一把刀。

命令行最省事，-s cumtime 表示按累计时间排序：

python -m cProfile -s cumtime workload.py

真跑输出（本机实测，节选）：

         2003687 function calls (2003564 primitive calls) in 0.650 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        5/1    0.000    0.000    0.650    0.650 {built-in method builtins.exec}
        1    0.000    0.000    0.650    0.650 workload.py:1(<module>)
        1    0.009    0.009    0.644    0.644 workload.py:36(main)
        1    0.000    0.000    0.526    0.526 workload.py:29(build_report)
        1    0.076    0.076    0.325    0.325 workload.py:16(normalize_names)
   200000    0.055    0.000    0.208    0.000 __init__.py:183(sub)
        1    0.129    0.129    0.195    0.195 workload.py:6(parse_records)
      200000    0.089    0.089    0.089    0.089 {method 'sub' of 're.Pattern' objects}
        1    0.006    0.006    0.006    0.006 workload.py:22(summarize)

在代码里调用则更灵活，可以只看前 N 行：

import cProfile, pstats, io
from workload import build_report

raw = "\n".join(f"{i},User-{i}!!,{i * 1.5}" for i in range(200_000))
pr = cProfile.Profile()
pr.enable()
build_report(raw)
pr.disable()
s = io.StringIO()
pstats.Stats(pr, stream=s).sort_stats("cumulative").print_stats(8)
print(s.getvalue())

16.1.3 读懂 ncalls / tottime / cumtime

这四列是剖析的全部信息量，必须能一眼读出来：

列含义用途
ncalls调用次数判断「是不是在循环里被反复调」
tottime自身耗时（不含子调用）找真正的计算热点
cumtime累计耗时（含子调用）找「哪个高层入口最贵」
percall每次调用平均单次成本是否异常

用 -s tottime 重排同一份负载，热点立刻变了样：

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.128    0.128    0.194    0.194 workload.py:6(parse_records)
   200001    0.104    0.000    0.104    0.104 workload.py:37(<genexpr>)
   200000    0.092    0.000    0.092    0.092 {method 'sub' of 're.Pattern' objects}
        1    0.078    0.078    0.337    0.337 workload.py:16(normalize_names)
   200000    0.058    0.000    0.217    0.217 re/__init__.py:183(sub)

两个排序给出的结论不同，这正是指挥优化的关键：

  • 按 cumtime 排：normalize_names（0.325s）比 parse_records（0.195s）更贵——说明「清洗名字」才是整个流程的大头。
  • 按 tottime 排：parse_records 自身（0.128s）反而最大——说明它的成本花在函数自己身上，而不是调用的子函数。

两条信息合起来：normalize_names 贵是因为它调了 re.sub 20 万次（ncalls 那一列暴露的）；parse_records 贵是因为循环体本身。summarize 只有 0.006s——直觉里「加法循环」的嫌疑被证伪了。这就是「先测量」的价值。

注意 ncalls 里形如 5/1 的写法：斜杠左边是总调用、右边是「原始调用」，差值来自递归。看到 5/1 说明这条链路被递归或间接调用多次。

16.1.4 pyinstrument：采样剖析与调用树

cProfile 精确但开销大，且输出是扁平表格，看不出「谁调用了谁」。pyinstrument 5.1.3 是采样式剖析器：每隔一段时间抓一次调用栈，开销低（对生产友好），输出是缩进的调用树，一眼看清调用链。

from pyinstrument import Profiler
from workload import build_report

raw = "\n".join(f"{i},User-{i}!!,{i * 1.5}" for i in range(200_000))
p = Profiler(interval=0.001)   # 每 1ms 采样一次
p.start()
build_report(raw)
p.stop()
print(p.output_text(unicode=True, color=False))

真跑输出（本机实测）：

  _     ._   __/__   _ _  _  _ _/_   Recorded: 11:58:58  Samples:  478
 /_//_/// /_\ / //_// / //_'/ //     Duration: 0.504     CPU time: 0.499
/   _/                      v5.1.3

Profile at <string>:6

0.504 <module>  <string>:1
├─ 0.495 build_report  workload.py:29
│  ├─ 0.309 normalize_names  workload.py:16
│  │  ├─ 0.177 sub  re/__init__.py:183
│  │  │  ├─ 0.074 Pattern.sub  <built-in>
│  │  │  ├─ 0.052 _compile  re/__init__.py:330
│  │  │  │  ├─ 0.036 [self]  re/__init__.py
│  │  │  │  └─ 0.016 isinstance  <built-in>
│  │  │  └─ 0.051 [self]  re/__init__.py
│  │  ├─ 0.087 [self]  workload.py
│  │  ├─ 0.028 str.title  <built-in>
│  │  └─ 0.017 str.strip  <built-in>
│  └─ 0.179 parse_records  workload.py:6
│     ├─ 0.106 [self]  workload.py
│     └─ 0.035 str.split  <built-in>

调用树的读法很直接：越靠左越深，每个节点的时间是它子树的总和。这里 normalize_names（0.309s）下挂着 sub（0.177s），而 sub 又拆成 Pattern.sub 和 _compile——采样剖析把「调用链」摊开给你看，这正是 cProfile 的扁平表给不了的。[self] 表示「时间花在本帧自己的字节码上」，不含子调用，等价于 cProfile 的 tottime。

16.1.5 timeit：微基准的正确姿势

定位到热点后，常要比较两种写法的单点开销。这时别用 time.perf_counter() 手搓，timeit 会自动做「多次重复 + 取最优」，屏蔽启动噪声：

import timeit

setup = "items = [str(i) for i in range(1000)]"
t_join = timeit.timeit("'|'.join(items)", setup=setup, number=20000)
t_add  = timeit.timeit('s = ""\nfor x in items: s += x', setup=setup, number=20000)
print(f"join  : {t_join * 1000 / 20000:.6f} ms/次")
print(f"+=    : {t_add * 1000 / 20000:.6f} ms/次")
print(f"加速比: {t_add / t_join:.1f}x")

真跑（本机实测）：

join  : 0.008654 ms/次
+=    : 0.034492 ms/次
加速比: 4.0x

微基准的三条纪律：用 setup 把准备数据排除在计时外；number 要够大（让单次耗时落进可测量区间，但又别大到触发 GC 抖动）；只比一个变量。timeit 测的是「这段代码本身」，不要拿它去测整条业务流程——那是 profiler 的活。

16.1.6 sys.monitoring：3.12+ 的轻量追踪

sys.monitoring（Python 3.12 新增）是 CPython 暴露给工具作者的底层事件钩子：可以订阅「函数调用 / 返回 / 抛异常 / 执行行」等事件，自己写一个轻量计数器。它比 sys.settrace 快得多，因为只在你订阅的事件上回调。

import sys
mon = sys.monitoring           # 注意：是 sys 的属性，不是可 import 的子模块

TOOL = mon.PROFILER_ID
mon.use_tool_id(TOOL, "call-counter")
counts: dict[str, int] = {}

def on_call(code, offset, callable_obj, arg0):
    # code 是「发起调用」的那一帧，callable_obj 是被调用的对象
    counts[code.co_name] = counts.get(code.co_name, 0) + 1

mon.register_callback(TOOL, mon.events.CALL, on_call)
mon.set_events(TOOL, mon.events.CALL)

from workload import build_report
raw = "\n".join(f"{i},User-{i}!!,{i * 1.5}" for i in range(20_000))
build_report(raw)

mon.set_events(TOOL, 0)
mon.free_tool_id(TOOL)
for name, c in sorted(counts.items(), key=lambda kv: -kv[1])[:6]:
    print(f"{name:20s} {c}")

真跑（本机实测）：

parse_records        100001
normalize_names      60000
_compile             40327
sub                  40000
_parse               425
_optimize_charset    225
总事件数: 243883

关键在 CALL 事件的四个参数：code 是「调用方」的代码对象，callable_obj 才是被调用者。所以 parse_records 100001 的含义是「从 parse_records 这一帧里发起了 10 万次调用」（每行 5 次：strip/split/int/float/append）。用它做调用次数画像，比 profiler 更轻、更可控，适合在生产里挂一个「可疑函数的调用频次」告警。

16.1.7 火焰图怎么读

cProfile 和 pyinstrument 给的是函数级数据，火焰图把整棵调用栈按时间占比画成一张图，适合看「宏观分布」。

本机未安装 py-spy 与 scalene，本节不贴它们的实测输出。 两者的定位：py-spy 是无需改代码、可 attach 到运行中进程的采样剖析器（官方标称对生产影响 <5% CPU），py-spy record -o flame.svg -- python script.py 生成火焰图；scalene 同时分析 CPU、内存与「Python 时间 vs C 时间」，能直接指出「哪部分是 numpy 干的、哪部分是你的循环」。装了之后再按它们的文档跑。

火焰图的读法只有三条，记牢就够：

  • 横轴是时间占比，不是时间线。越宽说明这块占的时间越多，优先优化最宽的那条。
  • 纵轴是调用栈深度，从底向上是「谁调用谁」。底部的宽条是「入口」，顶部的尖塔是「叶子」。
  • 颜色是随机的，不代表热度。不要被颜色误导，永远只看宽度。

有了火焰图，你会得到一个反直觉的常识：火焰图顶部那些「密密麻麻的小尖塔」往往不是瓶颈，真正的瓶颈是底部那几根又宽又平的柱——它们才是时间花掉的地方。

16.1.8 剖析结果的落地顺序

拿到数据后，优化的优先级是固定的：

优先级信号动作
1cumtime 最高的入口先确认它是不是必经路径，再拆子调用
2tottime 最高的叶子算法/数据结构层面的改写（见 16.2）
3ncalls 异常大的函数消除重复调用（缓存、批量）
4全局解释器限制判断 CPU 密集还是 I/O 密集，选并发模型

延伸阅读

小结

  • 不测量不优化：先用 profiler 拿到证据，再动手；改前记基线，改后测比值，一次只改一个变量。
  • cProfile 是确定性剖析：cumtime 找「哪个入口最贵」，tottime 找「哪个叶子自己最耗」，ncalls 暴露「谁被反复调用」。
  • pyinstrument 5.1.3 是采样剖析：开销低、输出调用树，能看清「谁调用了谁」，适合看调用链结构。
  • timeit 只做微基准：自动多次取优、用 setup 排除准备数据，比手搓 perf_counter 更可信。
  • sys.monitoring（3.12+） 是底层事件钩子，CALL 事件里 code 是调用方、callable_obj 是被调方，可自建轻量计数器。
  • 火焰图看宽度不看颜色，底部宽柱才是瓶颈；py-spy/scalene 本机未装，定位见正文。

本节只回答「哪里慢」。定位到热点之后，怎么改才有效，取决于瓶颈属于哪一类——下一节把瓶颈分成 CPU、内存、I/O 三类，逐一给出可量化的优化手法。

阅读导航：上一节：云平台部署与 Serverless · 下一节：CPU·内存·I/O 三类瓶颈的定位与优化 。

继续阅读

探索更多技术文章

浏览归档，发现更多关于系统设计、工具链和工程实践的内容。

全部文章 返回首页

「python」更多文章

  1. 《Python高级编程》目录
  2. 《Python高级编程》11.3 PEP 流程与版本迁移策略
  3. 《Python高级编程》11.2 嵌入式与自由线程运行时