🏠 总目录📚 本教程 05 · 怎么量:计时、剖析、内存 ← →
📑 本页目录(点开跳转)

05 · 怎么量:计时、剖析、内存

⏱ 90 分钟 | ⭐ 全站到处在教「怎么提速」,没有一章教「怎么知道快没快」——同一处改动,单次计时量出 6.7 倍和 1.5 倍两个矛盾结论,重复测量取最小值才稳定在 2.0 倍


🎯 一句话

「我觉得这里慢」是没有信息量的,改完之后「我觉得快了」同样没有。 这一章给三样工具和它们各自的脾气:计时回答「一共多久」,剖析回答「时间花在哪一行」,内存量峰值回答「会不会被 OOM 杀掉」。⚠️ 三样都有能把你骗到的地方,本章一半篇幅在讲那些地方。


🧩 一、三个时钟,各管各的

Python 手上不止一个时钟,它们数的不是同一件事:

# 你手上的三个时钟分别是什么脾气
import time

for name in ("time", "perf_counter", "process_time", "monotonic"):
    info = time.get_clock_info(name)
    print("%-13s 精度 %.9f s | 会不会被系统调时间影响: %s" % (
        name, info.resolution, "会" if info.adjustable else "不会"))

本机(Windows 11 / CPython 3.13)输出:

对照

time 精度 0.000000100 s | 会不会被系统调时间影响: 会

perf_counter 精度 0.000000100 s | 会不会被系统调时间影响: 不会

process_time 精度 0.000000100 s | 会不会被系统调时间影响: 不会

monotonic 精度 0.000000100 s | 会不会被系统调时间影响: 不会

⚠️ 注意第一列:网上流传的「Windows 上 time.time() 精度只有 15.6 毫秒」在这个版本上已经不成立了,四个时钟都是 100 纳秒。别照抄那条过时的理由。

⭐ 真正的区别在第二列:time.time() 是墙上的日历钟,它会被调。NTP 校时、夏令时切换、虚拟机挂起恢复、有人手动改了系统时间——只要发生在你两次取值之间,你的测量结果就是垃圾,而且可能是负数。perf_counter 是单调的,它唯一的用途就是量间隔,天生免疫这些。

第三个时钟数的是另一件事:

# perf_counter 数的是墙上的时间,process_time 数的是 CPU 真给你的时间
import time

t1 = time.perf_counter(); c1 = time.process_time()
time.sleep(0.5)                      # 等待:墙上的钟在走,CPU 没在为你干活
s = sum(i * i for i in range(2_000_000))
t2 = time.perf_counter(); c2 = time.process_time()

print("perf_counter (墙上时间)  %.3f s" % (t2 - t1))
print("process_time (CPU 时间)  %.3f s" % (c2 - c1))
print("差值 ≈ 花在等待上的时间     %.3f s" % ((t2 - t1) - (c2 - c1)))

对照

perf_counter (墙上时间) 0.747 s

process_time (CPU 时间) 0.172 s

差值 ≈ 花在等待上的时间 0.575 s

⭐ 这个差值本身就是诊断信息:两者接近,说明你的程序在真算;差得远,说明大部分时间在等(网络、磁盘、锁、被别的进程挤掉)。⭐ 这正是 04 章那张选择表的入口条件——在等就上 async 或线程,在算才考虑进程。

📋 规矩:

想知道 用哪个
一段代码跑了多久 ⭐ time.perf_counter(),无一例外
这段时间里 CPU 真为我干了多少活 time.process_time()
现在是几点、日志时间戳 time.time()(只用来记录时刻,不用来算间隔)

⚠️ 二、单次测量是没有信息的

这是本章最重要的一节。先看一个真实的翻车。

下面这个计时上下文管理器是最常见的写法(@contextmanager 的机制见 03 章),拿它来验证一处优化:

# 量 → 改 → 再量:一个可复用的计时上下文管理器
import contextlib, time

@contextlib.contextmanager
def timed(label):
    t = time.perf_counter()
    try:
        yield
    finally:
        print("%-22s %7.1f ms" % (label, (time.perf_counter() - t) * 1000))

rows = [i * 0.5 for i in range(200_000)]

def normalize(x, lo=0.0, hi=100.0):
    return (x - lo) / (hi - lo)

with timed("改之前(调函数)"):
    out1 = [normalize(x) for x in rows]

with timed("改之后(算式内联)"):
    out2 = [x / 100.0 for x in rows]

print("结果一样吗:", out1 == out2)

💀 同一个脚本,连着跑两次:

对照

改之前(调函数) 108.6 ms

改之后(算式内联) 16.1 ms ← 快了 6.7 倍

结果一样吗: True

对照

改之前(调函数) 69.8 ms

改之后(算式内联) 46.9 ms ← 快了 1.5 倍

结果一样吗: True

⭐ 同一处改动,两次运行给出「6.7 倍」和「1.5 倍」两个结论。 如果你只跑了第一次,会去汇报「优化了 6.7 倍」;只跑了第二次,可能觉得「不值得改」。两个结论都是噪声。

⚠️ 那个 try / finally 不是装饰:没有它,被计时的代码一抛异常,timed 就不会打印任何东西——你会以为程序卡住了,其实是计时器把异常吞在半路。

换成重复测量取最小值,结论立刻稳定:

# 同一处改动,用 timeit 重复测量取最小值
import timeit

setup = """
rows = [i * 0.5 for i in range(200_000)]
def normalize(x, lo=0.0, hi=100.0):
    return (x - lo) / (hi - lo)
"""
before = min(timeit.repeat("[normalize(x) for x in rows]", setup, repeat=9, number=5)) / 5
after = min(timeit.repeat("[x / 100.0 for x in rows]", setup, repeat=9, number=5)) / 5
print("改之前 %.1f ms | 改之后 %.1f ms | 快了 %.1f 倍"
      % (before * 1000, after * 1000, before / after))

连跑三次:

要点

改之前 21.9 ms | 改之后 9.5 ms | 快了 2.3 倍

改之前 22.5 ms | 改之后 11.4 ms | 快了 2.0 倍

改之前 23.8 ms | 改之后 12.1 ms | 快了 2.0 倍

⭐ 2 倍上下才是真实答案,而它需要重复 9 轮才浮出来。(⚠️ 这台机器当时还跑着别的活,你那里的绝对毫秒数一定不同——要看的是三次运行给出的是同一个结论。)


⭐ 三、为什么取最小值,不取平均

看一眼分布就明白了:

# timeit.repeat 为什么看最小值:噪声只会往上加,不会往下减
import statistics, timeit

setup = "data = list(range(20000))"
stmt = "sum(x * x for x in data)"

rs = timeit.repeat(stmt, setup=setup, repeat=15, number=20)
per = [r / 20 for r in rs]           # 除以 number,换算成「一次」的耗时

print("15 轮,每轮 20 次,单次耗时(毫秒):")
print("  ".join("%.2f" % (p * 1000) for p in sorted(per)))
print("最小值 %.2f ms | 中位数 %.2f ms | 平均 %.2f ms | 最大值 %.2f ms" % (
    min(per) * 1000, statistics.median(per) * 1000,
    statistics.mean(per) * 1000, max(per) * 1000))
print("最大值比最小值大 %.0f%%" % ((max(per) / min(per) - 1) * 100))

要点

15 轮,每轮 20 次,单次耗时(毫秒):

0.86 1.09 1.14 1.18 1.22 1.28 1.33 1.38 1.43 1.47 1.61 1.95 2.00 2.25 3.86

最小值 0.86 ms | 中位数 1.38 ms | 平均 1.60 ms | 最大值 3.86 ms

最大值比最小值大 347%

⭐ 这个分布是单边的:左边被一堵墙挡住(0.86 ms 是这段代码在这台机器上真正需要的时间,物理上不可能更快),右边拖着一条长尾(3.86 ms 那次是被别的进程抢了 CPU、或者赶上一次 GC、或者缓存被别人挤掉了)。

统计量 它回答什么问题 什么时候用
⭐ 最小值 这段代码最好能有多快 比较两种写法哪个更优——你要的是代码本身的差别,不是当天机器的忙闲
中位数 / 平均 在当前这台机器的当前负载下,典型一次要多久 估算「跑完全量要几小时」这类容量问题
⚠️ 最大值 / P99 最差情况 线上服务的延迟指标——那是另一件事,见文末链接

⚠️ 这不代表最小值就是「真实性能」。它是下界:你的代码在生产环境里只会更慢。最小值适合做 A / B 比较,不适合做容量规划。

timeit 自己也是这个立场——命令行版本直接把结论写在输出里:

> python -m timeit -s "data=list(range(20000))" "sum(x*x for x in data)"
500 loops, best of 5: 793 usec per loop

⭐ best of 5,不是 average of 5。

📋 timeit 的三个参数怎么定:

参数 意思 怎么定
number 一轮里连着跑几次,结果是这几次的总和 让一轮的总时长落在 0.1~1 秒。太小会被计时开销淹没
repeat 跑几轮 ⭐ 至少 5,机器忙的时候 10~15
setup 准备工作,不计入时间 造数据、import、定义函数全放这里

⚠️ number 和 repeat 是两件事,最容易混:repeat(..., repeat=15, number=20) 返回 15 个数,每个数是 20 次的总和。要换算成「单次」得自己除以 number——上面那段的 r / 20 就是干这个的。⚠️ 忘了除,你的所有数字会整整大 20 倍,而且看起来毫无破绽。


⚠️ 四、三样会让你测出假数字的东西

# 三样会让你测出假数字的东西
import functools, time, timeit

# ① 第一次里混着一次性的钱
t = time.perf_counter(); import numpy as np
print("① import numpy 这一次就要 %.3f s —— 而你想测的那段可能只有几毫秒"
      % (time.perf_counter() - t))
a = np.random.rand(2_000_000)
runs = []
for _ in range(5):
    t = time.perf_counter(); a.sum(); runs.append(time.perf_counter() - t)
print("   同一句 a.sum() 连测 5 次(ms): " + " ".join("%.2f" % (r * 1000) for r in runs)
      + " ← 最大是最小的 %.1f 倍" % (max(runs) / min(runs)))

# ② 缓存:第二次量的根本不是同一件事
@functools.lru_cache(maxsize=None)
def slow(n):
    return sum(i * i for i in range(n))

t = time.perf_counter(); slow(2_000_000); c1 = time.perf_counter() - t
t = time.perf_counter(); slow(2_000_000); c2 = time.perf_counter() - t
print("② 带缓存的函数:第一次 %.4f s | 第二次 %.7f s | 「快了」%.0f 倍" % (c1, c2, c1 / c2))

# ③ timeit 默认把垃圾回收关了
stmt = "[[0] * 100 for _ in range(3000)]"
off = min(timeit.repeat(stmt, repeat=7, number=20)) / 20
on = min(timeit.repeat(stmt, setup="import gc; gc.enable()", repeat=7, number=20)) / 20
print("③ 同一段代码:timeit 默认(GC 关) %.2f ms | 打开 GC %.2f ms" % (off * 1000, on * 1000))

操作步骤

  1. import numpy 这一次就要 0.174 s —— 而你想测的那段可能只有几毫秒
  2. 同一句 a.sum() 连测 5 次(ms): 2.77 3.92 1.91 2.01 3.13 ← 最大是最小的 2.1 倍
  3. 带缓存的函数:第一次 0.1842 s | 第二次 0.0000023 s | 「快了」80076 倍
  4. 同一段代码:timeit 默认(GC 关) 2.21 ms | 打开 GC 2.69 ms
# 陷阱 数字 怎么躲
① 一次性的钱混进来了:import、JIT 预热、首次内存分配、连接建立 import numpy 一次就要 0.174 s,而被测的 a.sum() 只有 2 毫秒——慢 80 倍的东西藏在里面 ⭐ 全部放进 setup=;或者先空跑一遍再开始计时
② ⭐ 缓存让你第二次量的不是同一件事 加了 lru_cache 的函数第二次「快了 8 万倍」——它根本没执行 每轮换不同的输入;或者显式 fn.cache_clear()
③ timeit 默认关掉了 GC 同一段代码 2.21 ms → 2.69 ms,差 22%。你的程序里 GC 是开着的 大量创建对象的代码,加 setup="import gc; gc.enable()"

⚠️ ①里那行「同一句 a.sum() 连测 5 次,最大是最小的 2.1 倍」值得单独看一眼——那五次之间什么都没变,代码、数据、机器全一样。2 倍的抖动是本底噪声。 所以「我改完快了 30%」这种结论,如果只测一次,基本没有意义。


🛑 读到这里可以停 —— 前半章讲完了(约 33 分钟)。 后半章还有:cProfile:时间花在哪一行 · 剖析器自己要钱,而且收费不均 · 内存:要量的是峰值,不是结束时 · 先量再改:固定四步 回来的时候不用重读,直接从下一节接着看就行。


🧩 五、cProfile:时间花在哪一行

计时告诉你「一共 3 秒」,剖析告诉你「其中 2.4 秒在哪」。标准库自带 cProfile(C 实现,开销小)和 pstats(读报告)。

# cProfile:一份最小但完整的剖析报告
import cProfile, pstats, io, random

def load(n=200_000):
    random.seed(0)
    return [random.random() * 100 for _ in range(n)]

def normalize(x, lo=0.0, hi=100.0):          # 被调用 20 万次的小函数
    return (x - lo) / (hi - lo)

def clean(rows):
    return [normalize(x) for x in rows]

def featurize(rows):
    return [r * r + r for r in rows]          # 一个大循环,不调用别的函数

def pipeline():
    rows = load()
    rows = clean(rows)
    return featurize(rows)

if __name__ == "__main__":
    pr = cProfile.Profile()
    pr.enable(); pipeline(); pr.disable()

    s = io.StringIO()
    (pstats.Stats(pr, stream=s)
        .strip_dirs()                 # ⭐ 去掉长路径,否则一行刷满屏幕
        .sort_stats("tottime")        # ⭐ 先按 tottime 排:谁自己最费
        .print_stats(6))
    print(s.getvalue())
         400009 function calls in 0.127 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.037    0.037    0.055    0.055 p07.py:4(load)
        1    0.037    0.037    0.059    0.059 p07.py:11(clean)
   200000    0.022    0.000    0.022    0.000 p07.py:8(normalize)
   200000    0.018    0.000    0.018    0.000 {method 'random' of '_random.Random' objects}
        1    0.011    0.011    0.011    0.011 p07.py:14(featurize)
        1    0.001    0.001    0.127    0.127 p07.py:17(pipeline)

⭐ tottime 和 cumtime 的区别就是全部:

列 含义 看最后那行 pipeline
tottime ⭐ 这个函数自己用掉的时间,不含它调用的别人 0.001 s —— 它自己几乎什么都没干
cumtime 从进这个函数到出来,总共过去多久(含所有子调用) 0.127 s —— 整个程序的时间都在它下面
ncalls 被调用了几次 1 次
percall 平均一次多久 两列各有一个

📋 怎么用这两列:

你想问 排哪一列 因为
哪一行代码最费 ⭐ sort_stats("tottime") 找真正的热点。normalize 自己占 0.022 s,是可以下手的地方
哪个环节最费 ⭐ sort_stats("cumtime") 找该砍掉的整块。clean 的 cumtime 0.059 s > load 的 0.055 s,说明清洗这一整段最贵
谁调用了这个热点 .print_callers("normalize") 热点常常不该改自己,该改调它 20 万次的那个人

⭐ ncalls 那一列经常比 tottime 更有用。normalize 单次只要 0.1 微秒,问题是它被调了 20 万次——能砍掉的不是这个函数,是那 20 万次调用(比如换成向量化的一次运算)。

💡 不想改代码就想剖析整个脚本:

要点

python -m cProfile -s tottime your_script.py | head -25

python -m cProfile -o out.prof your_script.py # 存成文件,再用可视化工具打开


⚠️ 六、剖析器自己要钱,而且收费不均

这是剖析报告最容易被误读的地方:它给你的秒数不是真实秒数,而且不同函数被多收的钱不一样多。

# 剖析器自己是要钱的,而且不是每个函数收一样多
import cProfile, time

def tiny(x):
    return x + 1

def many_small(n=1_000_000):        # 一百万次函数调用
    s = 0
    for i in range(n):
        s = tiny(s)
    return s

def one_big(n=1_000_000):           # 同样一百万次循环,但不调用函数
    s = 0
    for i in range(n):
        s = s + 1
    return s

def wall(fn):
    best = float("inf")
    for _ in range(3):
        t = time.perf_counter(); fn(); best = min(best, time.perf_counter() - t)
    return best

def under_profiler(fn):
    pr = cProfile.Profile()
    t = time.perf_counter()
    pr.enable(); fn(); pr.disable()
    return time.perf_counter() - t

for name, fn in [("many_small(一百万次函数调用)", many_small),
                 ("one_big  (一百万次纯循环)", one_big)]:
    a, b = wall(fn), under_profiler(fn)
    print("%s  裸跑 %.3f s | cProfile 下 %.3f s | 放大 %.1f 倍" % (name, a, b, b / a))

对照

many_small(一百万次函数调用) 裸跑 0.049 s | cProfile 下 0.290 s | 放大 5.9 倍

one_big (一百万次纯循环) 裸跑 0.031 s | cProfile 下 0.029 s | 放大 1.0 倍

💀 同一个剖析器,一个函数被放大 5.9 倍,另一个一点没变。

⭐ 原因很直接:cProfile 是确定性剖析器——它在每一次函数进入和退出时插一段记账代码。所以函数调用越密集,被多收的钱越多;纯循环不调用函数,几乎不被收费。

⚠️ 后果是真实的:裸跑时两者是 0.049 : 0.031(相差 1.6 倍),在剖析报告里变成 0.290 : 0.029(相差 10 倍)。排序没变,但比例被夸张了 6 倍。

📋 所以剖析报告的正确读法:

✅ 可以拿它做 ❌ 不能拿它做
找出「谁在最前面」,决定先改哪 拿报告里的秒数向别人汇报耗时
看 ncalls,发现「这个函数被调了 20 万次」 把几个函数的 tottime 加起来当总时间
改完之后再剖析一次,看热点有没有换人 用它比较「改前 0.29 s vs 改后 0.20 s」

⭐ 固定动作:用剖析器定位,用 timeit / perf_counter 验收。 定位和验收是两件事,用两套工具。

🗓️ 想要按行看的(这一节的工具会过期):line_profiler 装上之后给函数加 @profile、用 kernprof -l -v x.py 跑,能出每一行的耗时和占比;采样式的 py-spy 可以attach 到一个正在跑的进程上、开销只有百分之几,适合线上。⚠️ 两个都是第三方包。不想装东西的话,用第二节那个 timed 上下文管理器把可疑的段分块包起来,也能定位到「哪一段」。


🧩 七、内存:要量的是峰值,不是结束时

杀死你进程的是峰值,不是结束时还剩多少。 标准库的 tracemalloc 两个都给:

# 内存怎么量:峰值 vs 结束时,以及 getsizeof 为什么骗你
import sys, tracemalloc

def build_list(n=1_000_000):
    return [i * 2 for i in range(n)]      # 结果整个落地

def build_sum(n=1_000_000):
    return sum(i * 2 for i in range(n))   # 生成器,不落地

for fn in (build_list, build_sum):
    tracemalloc.start()
    r = fn()
    cur, peak = tracemalloc.get_traced_memory()
    tracemalloc.stop()
    print("%-11s 结束时占 %7.1f MB | 峰值 %7.1f MB" % (fn.__name__, cur / 1e6, peak / 1e6))
    del r

# getsizeof 只数「这个对象自己」,不数它指着的东西
lst = [i * 2 for i in range(1_000_000)]
print("getsizeof(列表)        %.1f MB  ← 只是一百万个指针" % (sys.getsizeof(lst) / 1e6))
print("加上里面每个 int       %.1f MB  ← 才是真账"
      % ((sys.getsizeof(lst) + sum(sys.getsizeof(x) for x in lst)) / 1e6))

对照

build_list 结束时占 40.4 MB | 峰值 40.4 MB

build_sum 结束时占 0.0 MB | 峰值 0.0 MB

getsizeof(列表) 8.4 MB ← 只是一百万个指针

加上里面每个 int 36.4 MB ← 才是真账

⭐ 两条结论:

  1. 一百万个数字,落地成列表要 40.4 MB,用生成器聚合是 0.0 MB。 这就是 02 章那套惰性写法的全部理由,⭐ 而这里是它的证据。
  2. ⚠️ sys.getsizeof 会骗你:它报 8.4 MB,因为它只数了列表里那一百万个指针;把指向的 int 对象也算上是 36.4 MB,差 4 倍多。⚠️ 对嵌套字典、对象树这类结构,getsizeof 的低估会更离谱。它只适合量单个扁平对象。

峰值和结束时不是一个数,这是最常见的 OOM 场景:

# 峰值和「结束时」是两个数,OOM 杀的是峰值
import os, tracemalloc

tracemalloc.start()

rows = [i * 2 for i in range(1_000_000)]        # 第一份
kept = [x for x in rows if x % 3 == 0]          # 第二份:此刻两份同时活着
snap = tracemalloc.take_snapshot()              # ⭐ 趁两份都在,拍一张
_, peak_both = tracemalloc.get_traced_memory()
del rows                                        # 放掉第一份
cur_after, _ = tracemalloc.get_traced_memory()
tracemalloc.stop()

print("两份都活着时的峰值 %.1f MB" % (peak_both / 1e6))
print("放掉第一份之后     %.1f MB" % (cur_after / 1e6))
print("\n分配得最多的三行(快照拍摄时刻):")
for st in snap.statistics("lineno")[:3]:
    fr = st.traceback[0]
    print("  %5.1f MB   %s:%d" % (st.size / 1e6, os.path.basename(fr.filename), fr.lineno))
峰值与释放后的内存
状态内存
两份都活着时的峰值43.4 MB
放掉第一份之后13.6 MB

分配得最多的三行(快照拍摄时刻):

保留原来的实测排名
快照中的源码行分配量
p11.py:640.4 MB
p11.py:72.9 MB

💀 峰值 43.4 MB,结束时 13.6 MB —— 相差 3.2 倍。 如果你只在函数返回后量一次,看到的是 13.6,然后在生产上被 OOM 杀掉,因为杀你的是那一瞬间的 43.4。⚠️ 真实场景里这个倍数只会更大:pd.read_csv 之后再 df[df.x > 0]、sorted(big)、list(...) 包一个已经很大的东西——每一处都是「新老两份同时活着」。

⭐ snapshot.statistics("lineno") 那几行是最有用的产出:它直接告诉你哪一行代码分配了多少(p11.py:6 那行占 40.4 MB)。

📋 三样工具分工:

工具 量什么 什么时候用
⭐ tracemalloc Python 对象分配的量,能定位到行,带峰值 找「哪一行吃内存」
sys.getsizeof 单个对象自己的字节数 ⚠️ 只对扁平对象可信
psutil.Process().memory_info().rss ⭐ 操作系统看到的整个进程占用 和「机器给了多少内存」对账。⚠️ 它含解释器本体、C 扩展和 numpy 的缓冲区,这些 tracemalloc 全看不见

⚠️ tracemalloc 自己也是有开销的(它给每次分配记账),别在生产里长开。


🛑 读到这里可以停 —— 已经读了约 63 分钟。 最后一段还有(约 24 分钟):先量再改:固定四步 · 检查点与走神救援 回来的时候不用重读,直接从下一节接着看就行。


📋 八、先量再改:固定四步

站内有一整节叫「⚡ 提速」(机器学习与深度学习基础 附录B),给了 AMP、torch.compile、n_jobs=-1 三招。⭐ 那三招都可能有效,但你按它改完之后,怎么知道改对了? 这四步就是那半边:

步 做什么 用什么 ⚠️ 常见错误
① 定基线 先量出「现在多久」,写下来 perf_counter 量整体,timeit 量小段 没记基线,改完只能凭感觉
② 定位 找到时间花在哪 cProfile 按 tottime 和 cumtime 各排一次 ⚠️ 拿剖析报告里的秒数当真实耗时(见第六节)
③ 只改一处 一次只动一个地方 —— 一次改三处,快了不知道哪个起作用、慢了不知道哪个拖后腿
④ 验收 用和①同一把尺再量一次 ⭐ 和①相同的方法、相同的输入 ⚠️ ①用 timeit、④用单次计时,那就回到第二节那个 6.7 倍 vs 1.5 倍的笑话了

⭐ 两条补充规矩:


🔗 这一章连到哪里

相关的地方 为什么
04 · GIL:为什么多线程救不了你 ⭐ 那一章的每个结论都是用本章的方法量出来的。「这个操作放不放 GIL」这个判据的验证手段就是本章第二、三节:同一个函数串行测一次、四线程测一次,看倍数
02 · 生成器与惰性求值 第七节那组 40.4 MB vs 0.0 MB 就是那一章的证据。⭐ 反过来说,在拿生成器改写之前先量一遍——数据小的时候它省不下什么,还搭进去可读性
03 · 装饰器与上下文管理器 第二节那个 timed 上下文管理器的机制在那里,包括 try / finally 为什么不能省
机器学习与深度学习基础 附录B-代码速查 ⭐ 它的「⚡ 提速」一节给了三招提速手段却没给测量手段,本章第八节补的就是那半边
AI全栈 15 · 可观测性 本章量的是你本地一段代码;线上一个服务要量的是 P50 / P95 / P99 和吞吐,那是另一套东西。⚠️ 注意立场差别:本章看最小值(比代码),线上看尾部(比体验)
模型上线之后 18 · 成本与容量 ⚠️ 本章第三节说「最小值不适合做容量规划」——容量该怎么算在那里
AI基础设施 04 · Roofline与MFU GPU 上「快没快」是另一套判据(算力墙还是带宽墙)。⭐ 本章的工具在 GPU 上会给出误导性结论——CUDA 调用是异步的,perf_counter 量到的可能只是「发出去」的时间

✅ 检查点

  1. time.time() 和 time.perf_counter() 的真正区别是什么?(⚠️ 本章实测否定了哪个流传很广的理由?)
  2. process_time 和 perf_counter 的差值告诉你什么?它怎么帮你决定该用线程还是进程?
  3. 本章那个「改之前 / 改之后」的例子,单次计时给出了哪两个矛盾结论?重复测量取最小值之后是多少倍?
  4. timeit 为什么取最小值不取平均?那个 15 个数的分布长什么样(最小、平均、最大分别多少)?
  5. 最小值不适合用来做什么?为什么?
  6. timeit.repeat(repeat=15, number=20) 返回几个数?每个数是什么?忘了换算会怎样?
  7. 三样会让你测出假数字的东西分别是什么?各自的实测数字是多少?
  8. tottime 和 cumtime 的区别是什么?本章报告里 pipeline 这一行两列分别是多少,说明了什么?
  9. 为什么剖析报告里的秒数不能直接汇报?本章那两个函数被 cProfile 放大了几倍?正确的分工是什么?
  10. 为什么量内存要量峰值?本章那个例子峰值和结束时差多少?sys.getsizeof 在哪里骗了你、差多少?
  11. 「先量再改」四步是什么?第 ④ 步最容易犯的错是什么?
👀 答案
  1. ⚠️ 本章实测否定了「Windows 上 time.time() 精度只有 15.6 毫秒」这个流传很广的理由 —— 在 CPython 3.13 / Windows 11 上 get_clock_info 显示四个时钟的精度都是 100 纳秒。真正的区别是 adjustable:time.time() 是会被调整的墙上日历钟(NTP 校时、夏令时、虚拟机挂起恢复、有人手动改时间),两次取值之间发生任何一件,结果就是垃圾甚至可能是负数;perf_counter 是单调的,专门用来量间隔。
  2. 差值 ≈ 花在等待上的时间(本章实测:墙上 0.747 s、CPU 0.172 s、差 0.575 s)。两者接近说明在真算,差得远说明在等——这正是 04 章选择表的入口条件:在等就上 async 或线程,在算才考虑进程。
  3. 同一个脚本连跑两次,给出「快了 6.7 倍」(108.6 → 16.1 ms)和「快了 1.5 倍」(69.8 → 46.9 ms)两个矛盾结论。用 timeit.repeat(repeat=9, number=5) 取最小值之后,三次运行稳定给出 2.3 / 2.0 / 2.0 倍 —— 2.0 倍才是真实答案。
  4. 因为分布是单边的:左边有一堵物理的墙(代码不可能比它真正需要的时间更快),右边拖着噪声长尾(被别的进程抢 CPU、赶上 GC、缓存被挤掉)。实测 15 个数排序后是 0.86 … 3.86 ms,最小 0.86、中位 1.38、平均 1.60、最大 3.86,最大值比最小值大 347%。取最小值就是把噪声剥掉,留下代码本身的差别。timeit 命令行自己也写着 best of 5,不是 average。
  5. ⚠️ 不适合做容量规划。最小值是下界——你的代码在生产环境里只会更慢。它适合做 A / B 比较(比两种写法),估「跑完全量要几小时」要用中位数或平均,线上延迟要看 P95 / P99。
  6. 返回 15 个数,每个数是连着跑 20 次的总和。⚠️ 忘了除以 number,所有数字会整整大 20 倍,而且看起来毫无破绽。
  7. ① 一次性的钱混进来:import numpy 一次就要 0.174 s,而被测的 a.sum() 只有 2 毫秒(藏了个慢 80 倍的东西);② 缓存:加了 lru_cache 的函数第二次「快了 80076 倍」,因为它根本没执行;③ timeit 默认关掉了 GC:同一段代码 2.21 ms → 2.69 ms,差 22%。另外那行「同一句 a.sum() 连测 5 次,最大是最小的 2.1 倍」说明2 倍的抖动是本底噪声,只测一次的「快了 30%」基本没意义。
  8. tottime 是这个函数自己用掉的时间(不含它调用的别人),cumtime 是从进去到出来总共过去多久(含所有子调用)。报告里 pipeline 这一行是 tottime 0.001 / cumtime 0.127 —— 它自己几乎什么都没干,整个程序的时间都挂在它下面。找热点排 tottime,找该砍掉的整块排 cumtime。另外 ncalls 常常更有用:normalize 单次只要 0.1 微秒,问题是它被调了 20 万次。
  9. 因为 cProfile 是确定性剖析器,在每次函数进入和退出时插记账代码,所以函数调用越密集被多收的钱越多。实测 many_small(一百万次函数调用)裸跑 0.049 s → 剖析下 0.290 s,放大 5.9 倍;one_big(一百万次纯循环)0.031 → 0.029,放大 1.0 倍。裸跑时两者相差 1.6 倍,报告里变成相差 10 倍——排序没变,比例被夸张了 6 倍。正确分工:用剖析器定位,用 timeit / perf_counter 验收。
  10. 因为 OOM 杀的是峰值,不是结束时还剩多少。实测:两份列表同时活着时峰值 43.4 MB,del 掉第一份后是 13.6 MB,相差 3.2 倍。sys.getsizeof 报一百万元素的列表只有 8.4 MB,因为它只数了那一百万个指针;把指向的 int 也算上是 36.4 MB,差 4 倍多,对嵌套结构低估更离谱。另外 tracemalloc 看不见 numpy 缓冲区和 C 扩展的内存,要和机器对账得用 psutil 的 RSS。
  11. ① 定基线并写下来;② 用 cProfile 定位(tottime 和 cumtime 各排一次);③ 一次只改一处;④ 用和①同一把尺再量一次。⚠️ 第 ④ 步最容易犯的错是换了尺——①用 timeit、④用单次计时,那就回到第二节那个「6.7 倍 vs 1.5 倍」的笑话。补充两条:先确认结果没变(out1 == out2,优化最常见的失败模式是「快了但算错了」且不报错),以及别优化不在热点上的东西(占 2% 的函数优化到 0 也只快 2%)。

🛑 可以停在这里

⚡ 走神救援

⭐ 「我觉得这里慢」和「我觉得快了」都是零信息。 三样工具各管一件事:计时回答「一共多久」、剖析回答「时间花在哪一行」、内存峰值回答「会不会被 OOM 杀掉」。

时钟只用 time.perf_counter()。⚠️ 「Windows 上 time.time() 只有 15.6 ms 精度」那条流传很广的理由在新版本上已经不成立;真正的区别是 time.time() 会被调整——NTP 校时、夏令时、虚拟机挂起恢复发生在两次取值之间,结果就是垃圾甚至负数。⭐ perf_counter 和 process_time 的差值就是花在等待上的时间,那正是「选线程还是选进程」的入口条件。

⚠️⚠️ 本章最重要的一条:单次测量没有信息。 同一个脚本连跑两次,同一处改动量出「快了 6.7 倍」和「快了 1.5 倍」两个互相矛盾的结论;换成 timeit.repeat 取最小值,三次都稳定在 2 倍出头。

⭐ 为什么取最小不取平均:分布是单边的——左边有物理的墙、右边全是噪声长尾,实测最大值能比最小值大三倍多。⚠️ 但最小值是下界,只适合 A/B 比代码,不适合做容量规划。

⚠️ repeat=15, number=20 返回的是 15 个数,每个是 20 次的总和,忘了除会整整大 20 倍。

三样让你测出假数字的东西:一次性的开销(import 比被测代码贵一个数量级)、⭐ 缓存(第二次「快了几万倍」是因为它根本没执行)、timeit 默认关了 GC。

⭐ 剖析:tottime 是函数自己用掉的、cumtime 是含子调用的——找热点排 tottime,找该砍的整块排 cumtime;而 ncalls 常常更有用(单次 0.1 微秒不是问题,被调二十万次才是)。⚠️ 剖析器自己要钱,而且对小函数收费格外重。

下一节 👉 06-类型标注是给工具看的.md

打卡记录保存在你的浏览器里,首页能看到总进度