性能剖析工具链深挖：cProfile、pstats、tracemalloc、采样 profiler

更新时间：2026-09-03。本文回答：Python 程序慢，到底用什么工具、怎么定位到那一行/那个函数？「剖析」有两种根本不同的流派——确定性追踪和采样，各自的代价和盲区是什么？pstats 报告里 tottime 和 cumtime 到底差在哪？内存涨了，怎么知道是哪一行分配的、是不是泄漏？ 本站主线是 Linux 性能剖析（perf 那一套），这一篇把同一套「先观测再优化」的方法论落到 Python 进程内部：01 · 性能优化路径 讲的是「优化分哪几层」，这一篇专讲测量工具本身——不测量就优化等于蒙眼开枪。5 个 demo 全部在服务器（CentOS 7，4 核，Python 3.6.8，纯标准库）实测，代码见文末「代码位置」。

一、两大流派：确定性追踪 vs 采样

剖析器（profiler）回答的核心问题是「时间花在哪了」，但回答方式分两派，这是理解所有工具的总纲：

	确定性追踪（deterministic / tracing）	采样（sampling）
代表	cProfile、sys.setprofile、profile	pyinstrument、py-spy、本文 d4 手写版
原理	在每次函数调用/返回时插桩，记一笔事件	每隔固定时间（如 1ms/2ms）打断进程，看当前栈在哪
数据	精确：调用次数、每次耗时，一个不漏	统计近似：某栈被采到的次数 ≈ 它占的时间比例
开销	较高（每次调用都付追踪税），但 cProfile 用 C 写已经很低	极低（只有定时中断本身），可长期挂在生产进程
盲区	只在函数边界触发；C 内建/睡眠等待的墙钟时间归到调用它的 Python 帧	采不到比采样间隔更短的短命函数；统计有噪声
适合	开发期、离线跑一遍、要精确调用次数	生产环境、长期运行、慢在 IO/锁/睡眠的程序

一句话：追踪派给你精确的「调用次数 + 函数自耗时」，采样派给你低扰动的「墙钟时间分布」，还能看到程序在「等」什么。 后面 d1/d3/d5 讲追踪派，d4 手写一个采样 profiler，d2 是独立的内存维度。

值得一提的是，这跟内核侧 perf record 的采样是同一个思想——perf 每隔 N 个时钟中断采一次指令指针（IP），聚合出热点；py-spy 对 Python 进程做的事几乎一样，只是读的是 CPython 的栈而不是原生栈。而 cProfile 的「每次调用插桩」则对应内核侧的 ftrace/函数追踪：精确但有开销。

二、cProfile：确定性追踪的主力，开销其实很低

cProfile 是标准库自带的默认 profiler，推荐指数远高于纯 Python 实现的 profile 模块。原因就在它的钩子是用 C 写的（底层 _lsprof）：每次函数调用/返回触发的回调不走 Python 字节码，追踪税被压得很低。

demo1（d1_cprofile_overhead/cprofile_overhead.py）让同一份混合 workload（Python 算术循环 + 大量 list.append/sort 内建调用）分别裸跑和带 cProfile 跑：

== profiling overhead (tracing every call/return) ==
    bare run      : 0.1901 s
    cProfile run  : 0.2065 s
    slowdown      : 1.09x  <-- 事件追踪的代价（C 实现，已经算便宜）

1.09x——也就是慢 9%。 这对开发期一次性剖析完全可以接受。（对比之下，纯 Python 回调的 sys.setprofile 同样 workload 慢 2.21x，见第四节。）所以「开 profiler 会把程序拖垮」是对 profile 模块或 Python 级钩子的旧印象，cProfile 一般不必担心。

三种用法：

# ① 命令行直接跑，结果存盘（推荐，等价于生产里 -o 留档离线分析）
python -m cProfile -o out.prof myscript.py
# ② 命令行跑完直接打印统计表
python -m cProfile myscript.py

# ③ 代码里精细控制（只剖析热点段，不把启动/导入时间算进去）
import cProfile
pr = cProfile.Profile()
pr.enable()
do_work()
pr.disable()
pr.dump_stats("out.prof")   # 存盘给 pstats / 工具读

关键习惯：把结果存成 .prof 文件（-o 或 dump_stats），而不是盯着终端那张表。 存盘后可以用 pstats 反复换着维度排序、过滤、对比，也能喂给可视化工具（gprof2dot 画调用图、snakeviz 画成矩形树图）。

三、pstats：tottime 和 cumtime 是两回事

.prof 文件用 pstats.Stats 读。理解表里四个列，剖析报告才读得懂：

• ncalls：调用次数（递归时显示 实际/原始 两个数）。
• tottime（internal time）：函数自己花的时间，不含它调用的子函数。
• cumtime（cumulative time）：调用链总时间，含这个函数 + 它所有后代。
• percall：tottime 或 cumtime 除以 ncalls。

demo1 的 cumtime 排序输出（节选）：

         120243 function calls in 0.205 seconds
   Ordered by: cumulative time
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.062    0.062    0.205    0.205 .../cprofile_overhead.py:14(work)
      120    0.133    0.001    0.133    0.001 {method 'sort' of 'list' objects}
   120000    0.007    0.000    0.007    0.000 {method 'append' of 'list' objects}
      120    0.003    0.000    0.003    0.000 {method 'reverse' of 'list' objects}

读法：

• 按 cumtime 排序，work 排第一（0.205s）——因为整个程序都在它的调用链里，它是「总时间」的根。但 cumtime 高不代表 work 自己慢，它可能只是调了很多重活。
• 按 tottime 排序，list.sort（0.133s）才是自耗时冠军，work 自己只有 0.062s。真正的 CPU 热点是排序，不是 work 的算术循环。
• 内建函数（{method 'sort'...}）有独立行：cProfile 能看到「调用了多少次内建」（120 次 sort、12 万次 append），但这些函数在 C 内部执行的那段时间，cProfile 无法再细分——它只在「Python 调 C」的边界记一笔。所以 cProfile 告诉你「sort 被调了 120 次、占 0.133s」，但 sort 内部怎么花的它看不到（那要上 perf 采原生栈）。

排查口诀：先用 cumtime 找到「哪条调用链最重」（定位入口/请求处理函数），再用 tottime 在那条链里找到「谁自己在烧 CPU」（定位叶子热点）。 一个函数如果 tottime ≈ cumtime，说明它是叶子热点——自己干完所有活、没再往下调；如果 cumtime ≫ tottime，说明它是个调度者，时间都花在它调用的子函数上。

demo5（d5_pstats_read/pstats_read.py）演示程序化读取和 print_callers（找谁调用了热点）：

-- top by cumtime --
   cum  0.171s  tot  0.000s  api_request    pstats_read.py:20
   cum  0.127s  tot  0.127s  transform      pstats_read.py:13
-- print_callers(transform): 谁调用了 transform --
   ...(transform)  <-  20  0.127  0.127  ...:20(api_request)

api_request 的 cumtime 0.171s 但 tottime 0.000s——它是调度者（自己只花在字典推导上，时间都在调用 transform）；transform 的 tottime≈cumtime=0.127s，是叶子热点。print_callers("transform") 直接告诉你它被 api_request 调了 20 次、累计 0.127s——这在大代码库里定位「这个热点函数到底是被哪条业务路径触发的」非常有用。

四、sys.setprofile：cProfile 的底层，但纯 Python 回调很贵

cProfile 不是魔法，它注册的是 CPython 提供的剖析钩子。sys.setprofile(callback) 让你在每个 Python 函数事件发生时收到回调，事件类型有四种：

• call：Python 函数被调用；return：Python 函数返回。
• c_call：调用了一个 C/内建函数；c_return：从 C 函数返回。

demo3（d3_setprofile_cost/setprofile_cost.py）先数事件，再对比三种跑法的开销：

== setprofile event counts (business(2000)) ==
    call      2002
    return    2002
    c_call    1
    c_return  0
== overhead comparison (business(60000)) ==
    bare                     0.0160 s
    cProfile (C hook)        0.0229 s
    setprofile (Python hook) 0.0353 s
    cProfile slowdown : 1.43x
    setprofile slowdown: 2.21x

这里 workload 是紧凑的 Python 算术循环（几乎不调内建，所以 c_call 只有 1 次），调用越密集，追踪税越明显。同样的事件流，cProfile 的 C 级钩子慢 1.43x，而纯 Python 回调慢 2.21x——差距来自：Python 回调本身是一次新的 Python 函数调用（要建帧、传参、走求值循环），几千万次事件就是几千万次额外的 Python 帧。这正好呼应 05 · 字节码与求值循环 讲的「函数调用即新建堆帧」的代价。

所以：

• cProfile = 把 setprofile 的回调换成了 C 实现，逻辑等价但税低，这就是为什么日常一律用 cProfile 而不是手写 setprofile。
• sys.setprofile / sys.settrace（后者还多了「每行」事件，更慢，是 pdb 调试器和 coverage.py 的基础）适合教学、定制统计（比如只统计某类函数、记录参数），不要拿它长期剖析生产进程。
• 还有个坑：setprofile 的回调如果 return 了另一个函数，那个函数会被当作「进入被调函数内部」的探针——想只统计边界事件就 return None。

五、采样 profiler：不追踪每次调用，定时打断看栈

追踪派的盲区是墙钟等待：如果程序慢在 time.sleep、等数据库、等锁、等网络 IO，cProfile 会把这段时间记在「发起调用的那个 Python 帧」的 tottime 里（因为睡眠期间没有函数返回事件），你会看到一个函数 tottime 很高，却以为是它在算，其实它在睡。

采样派解决这个问题：不关心调用边界，每隔固定时间把进程打断，快照当前调用栈。 某段代码（CPU 忙算或睡眠等待）只要占用墙钟时间，就会被按比例采到。pyinstrument、py-spy 都是这个原理；py-spy 甚至不用改目标进程代码（类似 perf 直接附加）。

demo4（d4_sampling_profiler/sampling_profiler.py）用 signal.SIGALRM + signal.setitimer(ITIMER_REAL, ...) 手写一个 2ms 间隔的墙钟采样器，跑一段「CPU 忙算 + sleep 模拟 IO」的混合负载：

== sampling profiler (wall-clock, sees CPU *and* waiting) ==
    total samples: 159 (interval 2 ms)
    -- where the top frame was (self time proxy) --
        68.6%  io_wait
        31.4%  cpu_hot
    -- hottest call stacks (cumulative/wall time proxy) --
        68.6%  <module> -> mixed -> io_wait
        31.4%  <module> -> mixed -> cpu_hot

要点：

• ITIMER_REAL 按真实墙钟计时，进程在 time.sleep 里挂起时信号照样触发，所以 io_wait（睡眠）被采到 68.6%——这段在 cProfile 里会被错误地堆到调用帧上，采样却如实反映「程序三分之二的墙钟时间在等」。这对排查「接口慢但 CPU 不高」这类问题是决定性的。
• 栈顶分布 ≈ self time，整条调用栈聚合计数 ≈ cumtime/墙钟占比——采样派用统计方式同时逼近了追踪派的两个核心指标。
• 开销 ≈ 定时中断本身（2ms 一次，每次沿帧链走几层），不随调用次数增长，所以可以长期挂在生产进程。代价是统计近似：比采样间隔（2ms）更短命的函数可能一次都采不到，占比有 ±几个百分点的噪声——想要更准就缩短间隔（开销上升）或跑久一点（样本多了就稳）。
• 手写版用信号，只能在主线程、Unix 上跑（Windows 无 ITIMER_REAL）；生产用 py-spy（基于进程间读栈，跨平台、不用改代码、能附到已运行进程）或 pyinstrument。

选择直觉：CPU 密集、要精确调用次数 → cProfile；慢在 IO/锁/睡眠、或要低扰动长期挂生产 → 采样（py-spy/pyinstrument）；想看 C 扩展/原生代码热点 → perf。 三者互补，不互斥。

六、tracemalloc：内存按「行」归因，揪出泄漏

前面都是 CPU/时间维度。内存涨了怎么办？标准库 tracemalloc 是 Python 3.4+ 自带的内存剖析器，它 hook 住 Python 的分配器，能记录每一块内存是在哪一行 Python 代码分配的。

demo2（d2_tracemalloc_line/tracemalloc_line.py）做三件事。先是三种分配风格的逐行归因：

== per-line allocated (top 5, current KB) ==
    +21584.8 KB  tracemalloc_line.py:31  big = [dict(idx=i, pair=(i,i*2)) for i in range(60000)]
     +6655.4 KB  tracemalloc_line.py:32  padded = [("item-%08d|" % i)*4 for i in range(60000)]
     +2161.1 KB  tracemalloc_line.py:33  compact = list(range(60000))

6 万个元素，字典+元组那行吃 21MB，大字符串 6.7MB，而 list(range(60000)) 只占 2.1MB——因为小整数是共享单例（02 · CPython 内部机制 讲过的小整数池），列表里只是 6 万个指针，没新建 6 万个 int。tracemalloc 直接把账记到具体行号，这是 tracemalloc.take_snapshot() 后 compare_to(snap, "lineno") 的功劳；加 traceback 参数（如 start(25) 保留 25 层栈）还能看「是谁的调用链分配的」。

再看释放与泄漏（衔接 09 · GC 与内存管理 的引用计数）：

== reference counting frees immediately vs global leak ==
    before            : traced 0.20 MB, RSS 124.8 MB
    after local_freed : traced 0.08 MB, RSS 124.8 MB  (局部对象已释放)
    after leaked()    : traced 9.29 MB, RSS 124.8 MB  (挂全局,未释放)
== leak attribution: still-held blocks by line (top) ==
      9436.6 KB  tracemalloc_line.py:55  LEAK.extend(b"y"*200 for _ in range(40000))

• local_freed() 里 4 万个 200B bytes，函数返回后引用计数归零立即释放，traced 从 0.20 掉到 0.08MB——和 09 篇 的「无环对象 del 即释放」完全一致。
• leaked() 把对象塞进全局 LEAK 列表，引用计数永不归零，traced 涨到 9.29MB 不回落；快照按行归因直接点到第 55 行就是泄漏点。

最重要的一个对比：traced 变了，RSS 全程 124.8MB 纹丝不动。 因为 RSS（这里用 resource.getrusage().ru_maxrss 读，是进程历史峰值）只升不降——CPython 把释放的内存留进自己的内存池（arena/pool）复用，通常不还给 OS。所以：

• 看「进程现在占多少物理内存、有没有触及容器上限」→ 用 RSS（/proc、ps、ru_maxrss）。
• 看「哪一行在分配、哪块内存没被释放、是不是泄漏」→ 用 tracemalloc（它统计的是 Python 堆当前存活字节，可升可降，还带行号）。
• tracemalloc 本身有开销（每次分配都记录），平时别常开，排查内存时再 start()。

七、什么时候用什么：一张速查表

场景	工具	流派/维度	开销	关键输出
开发期跑一遍找 CPU 热点	cProfile + pstats	追踪·时间	~1.1–1.5x	tottime/cumtime/ncalls、调用图
结果存盘反复分析/画图	cProfile -o x.prof → pstats/snakeviz/gprof2dot	追踪·时间	同上	.prof 文件
生产进程长期低扰动剖析	py-spy（附加，不改代码）/ pyinstrument	采样·墙钟	极低	火焰图、调用树占比
慢在 IO/锁/睡眠，CPU 不高	采样 profiler（pyinstrument/d4）	采样·墙钟	极低	等待时间也按比例采到
内存涨/怀疑泄漏/哪行分配	tracemalloc	追踪·内存	中（分配钩子）	按行/按调用栈的存活字节、快照 diff
进程占多少物理内存	RSS（/proc、ps、ru_maxrss）	系统·内存	无	峰值/常驻，只升不降
想看 C 扩展/native 热点	perf record/perf top	采样·原生	极低	原生栈火焰图
定制统计/教学理解钩子	sys.setprofile/settrace	追踪·事件	高（Python 回调）	自定义事件流
每次跑都想守住性能基线	pytest-benchmark / timeit	基准	—	耗时回归对比

排查顺序建议（和本站 perf 方法论 一致：先宏观后微观）：先 time/RSS 判断是慢在 CPU 还是内存还是等待 → CPU 热点用 cProfile（开发）或 py-spy（生产）→ 等待型问题上采样 → 内存问题上 tracemalloc → 怀疑 C 扩展再上 perf。

八、常见坑

坑	表现	处理
只看 cumtime 就优化	优化了 main/请求入口这种「调度者」，没用	cumtime 定位链路、tottime 定位叶子热点；tottime≈cumtime 才是真热点
把 tottime 高等同于「在算」	睡眠/IO 等待也算进调用帧的 tottime	慢但 CPU 不高时改用采样 profiler，能区分「算」和「等」
用纯 Python 的 profile 模块	慢几十倍，剖析本身改变结果	一律用 C 实现的 cProfile
手写 sys.setprofile 长期挂生产	Python 回调每次事件建帧，慢 2x+	生产用 py-spy/pyinstrument 采样
用 RSS 判断泄漏	RSS 只升不降，释放了也不回落	泄漏判定用 tracemalloc 存活字节/快照 diff
tracemalloc 常开	每次分配都记录，常态有开销	排查时 start()，平时关闭
采样间隔内的短命函数	热点函数一次没被采到	缩短间隔或拉长运行时间攒样本；要精确次数用 cProfile
看不到 C 内建内部耗时	{method 'sort'} 只有一行、无内部细分	那是 C 代码，cProfile 到边界为止；上 perf 采原生栈
非交互 ssh 跑 Python 中文报 ascii 错	UnicodeEncodeError（cron/ssh 无 LANG）	设 PYTHONIOENCODING=utf-8，或代码里 sys.stdout.reconfigure/包 TextIOWrapper

代码位置

5 个纯标准库 demo（CentOS 7 / 4 核 / Python 3.6.8 实测），在 demos/python-expert/profiling/：

• d1_cprofile_overhead/cprofile_overhead.py：cProfile 追踪开销（1.09x）+ pstats 的 cumtime/tottime 两种排序
• d2_tracemalloc_line/tracemalloc_line.py：tracemalloc 逐行归因 + 局部释放 vs 全局泄漏 + RSS 对比
• d3_setprofile_cost/setprofile_cost.py：setprofile 四类事件计数 + Python 回调(2.21x) vs cProfile(1.43x)
• d4_sampling_profiler/sampling_profiler.py：SIGALRM/ITIMER_REAL 手写采样 profiler（采到 io_wait 68.6%）
• d5_pstats_read/pstats_read.py：dump_stats 存盘 + pstats 程序化读取 + print_callers 找调用方
• run_all.sh：一键跑全部 5 个（d4 需 Linux/Unix，Windows 无 ITIMER_REAL）

一句话总结

Python 剖析就两件事——时间用 cProfile（精确追踪，开发期）或 py-spy/采样（低扰动，还能看到「等」），内存用 tracemalloc（按行归因、揪泄漏），RSS 只告诉你峰值不告诉你是谁；读报告先 cumtime 找链路、再 tottime 找叶子热点，永远先测量再优化。