开了日志，计时和调优结果都变了

主线位置：算子主线的 cubecl 一层，Client::launch_inner 提交内核、autotune 第一次遇到一个调优键的地方。autotune 的流程和缓存见 autotune，日志能看到什么见 #[cube] 内核。

flowchart TB
  env["CUBECL_DEBUG_LOG"] --> lvl["性能日志 Medium"]
  lvl --> block["每次启动都等设备做完"]
  block --> lo["测得启动开销 1.7 ms"]
  lo --> lim["时间上限放宽"]
  lim --> sc["第一个候选就短路"]
  lo --> db["吞吐量写进 default.db"]
  db --> later["之后不开日志的新键也照用"]

实验 crate pc-gpu，Metal，[n, n] f32 matmul，release 构建，M2 Max、macOS 27、rustc 1.99.0，cubecl 0.11.3。两个干净的运行目录 pc-dl-log 和 pc-dl-clean，各放一个空的 Cargo.toml（让 autotune 缓存落在各自的 target/environment）和一个 cubecl.toml，只打开 autotune 决策记录：

[autotune.decisions]
stdout = true

决策记录是一行 JSON，下面只摘出要点。测量时机器负载（uptime 1 分钟）在 50 到 80 之间。

现象

两个目录都从冷缓存开始，各跑一个进程，pc-dl-log 开 CUBECL_DEBUG_LOG=stdout，pc-dl-clean 不开。程序对每个尺寸先算一次 matmul 并 sync，再算 20 次：

pc-dl-log   (CUBECL_DEBUG_LOG=stdout, cold)
1024x1024 f32 matmul: first 33.697s, next 20 min 2.934ms median 5.668ms

pc-dl-clean (no log, cold)
1024x1024 f32 matmul: first 4.785s, next 20 min 1.966ms median 2.908ms
2048x2048 f32 matmul: first 1.229s, next 20 min 6.904ms median 20.243ms

开日志的第一次是 33.7 秒，日志本身两万多行。更要紧的是 autotune 的决定。开日志的那次，日志里：

Calculated bounds: Bounds { bounds: [AutotuneBound { resource: ResourceBound { amount: 2146435072, peak_per_s: 4235601110830.5986 }, threshold: 0.8 }, AutotuneBound { resource: ResourceBound { amount: 12582912, peak_per_s: 303517186482.37933 }, threshold: 0.8 }], launch_overhead: 1.706895ms } - limit: Some(2.340345ms)

 - Tuning: matmul_simple_cyclic_cmma (compilation & bench: 59.632417ms)
 - Tuning: matmul_simple_cyclic_cmma_multi_rows (compilation & bench: 0ns)
...
Short circuiting autotune. matmul_simple_cyclic_cmma is close enough to peak throughput.
Autotune[12] name matmul_simple_cyclic_cmma => BenchmarkComputations { mean: 1.554854ms, median: 1.56ms, variance: 0ns, min: 1.549708ms, max: 1.56ms }

两次的决策记录对照（fastest_index、实测了几个候选、屋顶线算出的上限）：

不开日志时 [14] 测得 1.328 ms，[12] 是 1.560 ms，所以 [14] 胜出；开日志时上限放宽到 2.34 ms，第一个候选 1.56 ms 就进了上限，其余候选没测。

然后在 pc-dl-log 目录里不开日志再跑一个进程，加一个新尺寸 2048（新的调优键，要重新调）：

2048 fastest_index 12 [(12, 'matmul_simple_cyclic_cmma')]
  launch_overhead {'secs': 0, 'nanos': 1706895} limit {'secs': 0, 'nanos': 6775737}

日志已经关了，新键用的仍是那次测出的 1.706895 ms 启动开销和 4.236e12 的计算峰值，又在第一个候选上短路。同一个尺寸在 pc-dl-clean 里实测了 6 个候选，选的是 [14]。

两边选中的内核差多少，用设备时间量（Device::profile_with 加 flush()，见 GPU 上第一次很慢、计时忽快忽慢），两个目录交替各跑两遍：

-- log dir (index 12)
1024x1024 f32 matmul device time, 20 samples: min 1.549ms median 1.556ms
2048x2048 f32 matmul device time, 20 samples: min 6.346ms median 8.058ms
-- clean dir (index 14)
1024x1024 f32 matmul device time, 20 samples: min 1.324ms median 1.331ms
2048x2048 f32 matmul device time, 20 samples: min 3.959ms median 7.272ms
-- log dir (index 12)
1024x1024 f32 matmul device time, 20 samples: min 1.550ms median 1.646ms
2048x2048 f32 matmul device time, 20 samples: min 5.560ms median 5.927ms
-- clean dir (index 14)
1024x1024 f32 matmul device time, 20 samples: min 1.322ms median 1.328ms
2048x2048 f32 matmul device time, 20 samples: min 4.010ms median 6.740ms

1024² 慢 17%（1.55 对 1.32 ms），2048² 的最小值慢 39% 到 60%。开过一次日志的目录，此后一直用着这组选择。

出处

override_from_env 看到 CUBECL_DEBUG_LOG 就同时把编译日志开到 Full、性能日志开到 Medium、autotune 日志开到 Full。性能日志的级别决定 Client::launch_inner 走哪条路：只有关掉或 Minimal（映射成 ProfileLevel::ExecutionOnly）时才是 device.submit 扔给设备线程就返回；Basic、Medium、Full 走「先测时间再提交」的分支，每次启动都要等设备做完。编译日志要源码时，wgpu 运行时还会用带调试层的实例（wgpu 与 Metal、autotune 的「没有蠢问题」）。

autotune 第一次遇到调优键时，先用屋顶线（计算峰值、带宽峰值、启动开销）算一个时间上限，候选进了上限就短路（disable_short_circuit 默认关）。启动开销和峰值不是每次都测，而是存进单独的吞吐量缓存（ThroughputCache::get_for_device，按运行时名、适配器名和显存大小命名），同一台机器上的所有键共用，和 autotune 结果一样落在 default.db 里。日志下测出的那组数因此被后来的进程继续使用，直到删掉缓存。

另一个开关 autotune-checks（burn 的 feature，传到 cubecl-runtime）是正确性调试用的：每次执行一个可调优的 op，都把所有候选各跑一遍、比对输出（LocalTuner::checks）。开着它的计时没有意义，本页没有再跑。

修法

• 计时、调优时不要开 CUBECL_DEBUG_LOG、CUBECL_DEBUG_OPTION（它的 debug、debug-full、profile、profile-medium、profile-full 都把性能日志开到 Basic 或更高），也不要开 autotune-checks。
• 想看 autotune 选了谁，用 [autotune.decisions]，它只多一个输出口，不改日志级别。上面 pc-dl-clean 的记录就是这样来的。
• 想看生成的内核源码，开日志跑完之后删掉缓存再计时：删除运行目录上方最外层 Cargo.toml 旁的 target/environment（或你固定的缓存目录）。或者干脆在一个单独的目录里看日志，这样它写的是另一份缓存。

怎么确认没中招

• 打开 [autotune.decisions] 跑一个新形状，看记录里的 launch_overhead：本机不开日志时是几微秒（本页 6.787 µs，autotune 页 3.6 µs），毫秒级就是被日志污染过的缓存。
• 同一记录里「实测候选」只有 1 个、日志里有 Short circuiting autotune，而上限是毫秒级时，要怀疑。
• 环境里没有残留的 CUBECL_DEBUG_LOG / CUBECL_DEBUG_OPTION。

小结

• CUBECL_DEBUG_LOG 把性能日志开到 Medium，每次内核启动都阻塞等设备；开着它测出的时间不能用。
• 冷缓存时它还污染 autotune：启动开销 1.7 ms、计算峰值减半，上限放宽，在第一个候选上短路，选中的 matmul 在 1024² 上慢 17%，2048² 上慢 39% 到 60%。
• 吞吐量测量和调优结果都写进 default.db，之后不开日志的进程照用；开过日志后要删缓存。
• 看决策用 [autotune.decisions]；autotune-checks 是正确性调试 feature，计时时不开。