GPU利用率99%却训练慢？用PyTorch Profiler与Kineto Trace定位性能瓶颈

我刚开始做GPU性能优化那阵子就遇到过一件让我特别困惑的事一块训练卡nvidia-smi里显示的利用率已经到 99%任谁看都是“满负荷运转”可训练一个 step 的实际耗时就是压不下去。后来我借着 PyTorch Profiler 背后的 Kineto 探针把 Trace 时间线拉出来一个事件一个事件地看才明白问题出在哪——那条 99% 是一条“忙但不一定高效”的统计曲线它完全看不见 kernel 之间的空白缝隙、数据搬运的等待以及隐藏的同步点。这篇就把我这套排查方法完整写出来。从 Kineto 底层探针的工作机制讲起再拆解 Trace 时间线里最常见的四重病灶最后落到 PyTorch Profiler 的实际使用和一次完整优化案例上。适合那些跟我一样明明看着 GPU 占用率拉满却总感觉训练速度不匹配的工程师也适合做大模型微调、多卡训练之前想先搞清楚瓶颈到底在哪的人。1. 99% 的利用率为什么不能信一个“很忙但不一定在干活”的统计口径1.1 利用率到底在统计什么很多同学对nvidia-smi里的 GPU-Util 有一个默认假设利用率高 计算单元吃饱了。这个假设在大多数场景下是错的。GPU 利用率这个数值统计的是采样周期内“GPU 上有引擎处于活动状态”的时间比例。只要有一个 kernel 在跑无论是 Tensor Core 在算矩阵乘法、显存控制器在做 H2D 拷贝、还是 copy engine 在搬运数据这 1 秒的采样周期都会计入“忙”的状态。换句话说它衡量的是“有没有活干”而不是“干的活是不是核心计算”。用一个工地上的类比来说GPU 是一个施工队利用率只告诉你工人们有没有在上班但它分不清你是在盖楼、在搬砖、还是在等上级指令。搬砖搬得再勤快大楼也盖不快。搬到极致工人们的“利用率”照样是 100%但工程进度就是上不去。所以在性能排查里我第一件事就是告诉自己别再盯着利用率这个单一指标了。它是筛选问题用的粗筛子不是定位问题用的放大镜。真正决定训练快慢的是 GPU 上的计算指令有没有在流水线里连续跑起来以及驱动这个流水线的 CPU 端有没有及时把后续指令喂到设备上。1.2 从聚合指标到逐事件记录硬件计数器能补充什么既然利用率是聚合指标那要看懂真实的性能瓶颈就必须把时间轴拆开逐条记录每个事件的发生时刻和持续时长。这就是 Trace 的强项。PyTorch Profiler 背后的 Kineto 探针不仅能记录 CPU 侧每个算子的调用时间、GPU 侧每个 kernel 的执行时间还能通过设备计数器拿到更细致的硬件级数据比如 SM 的活跃比例、显存吞吐、Tensor Core 的占用情况。这些数据比 nvidia-smi 的利用率高出整整一个维度利用率只告诉你 GPU 忙不忙硬件计数器能告诉你 GPU 到底在忙什么类型的活、计算流水线有没有打满。我在实际诊断中一般遵循这样一个顺序先用 PyTorch Profiler 跑一小段训练导出 Trace 时间线然后重点观察 kernel 与 kernel 之间的间隔、H2D/D2H 传输块、同步点再看 SM 活跃度和显存吞吐。只要这几个数据对齐慢的原因基本就浮出水面了。2. Kineto 探针的工作链路CUPTI 回调如何把每次 kernel 启动“拍”下来2.1 探针在整个性能体系里的定位Kinetolibkineto是 PyTorch Profiler 在 NVIDIA GPU 上做底层采集的核心库。你可以把它理解成一个“行车记录仪”它在不改动训练代码的前提下往 CUDA 的运行时层和驱动层挂上监听器把每一次 CUDA API 调用、每一次 kernel 启动、每一段显存拷贝都记录成带时间戳的事件。它和torch.profiler.profile的关系是这样的PyTorch Profiler 负责给用户提供友好的 Python 接口Kineto 负责在底层干脏活累活。你在 Python 端看到的ProfilerActivity.CPU、ProfilerActivity.CUDA最终都会转化成对 Kineto 的采集请求Kineto 再通过 CUPTICUDA Profiling Tools Interface去跟 CUDA 驱动打交道。有人会问NVIDIA 自己不是有 Nsight Systems 吗能不能直接用当然可以。实际上 Nsight Systems 的底层也建立在 CUPTI 之上采集原理和 Kineto 高度相似。区别在于PyTorch Profiler 和 Kineto 的集成度更高能把 Python 算子栈、PyTorch 框架内部活动和 CUDA kernel 事件统一对齐到同一条时间线上这对定位框架层问题非常有用。2.2 CUPTI 回调与 Activity Buffer两个时间维度的采集Kineto 的采集分成两条链路对应两个时间维度第一条是 CUPTI 的回调机制。CUDA 的 runtime API 被调用时CUPTI 可以注册回调函数Kineto 通过这些回调记录 CPU 端调用cudaMemcpy、cudaLaunchKernel等 API 的时刻和参数。这条链路回答的是“CPU 端什么时间发起了什么指令”。第二条是 Activity Buffer 机制。Kernel 在 GPU 上真正开始执行和结束的时刻CPU 端是无法直接通过普通回调感知的因为 kernel 是异步执行的。CUPTI 会在驱动层维护一个缓冲区当 GPU 侧的事件完成时驱动把完整的时间戳写进缓冲区Kineto 定期把缓冲区里的数据取出来解析成事件记录。这条链路回答的是“GPU 端什么时间真正执行了什么 kernel”。两条链路的数据最后被 Kineto 对齐到同一个时间坐标系里导出成 Chrome Tracing 格式的 JSON 文件。这就是你在chrome://tracing或者perfetto里看到的那些五颜六色的时间条。关键点在于CPU 时间线和 GPU 时间线是叠在一起的你一眼就能看出某个时间窗口里到底是 CPU 在忙、GPU 在忙还是两边都在干等。2.3 为什么 Trace 能看到 99% 利用率看不见的缝隙利用率是一个在 1 秒时间窗里统计出来的百分比它天然会把时间轴上的细粒度信息“压扁”。比如一个训练迭代耗时 300ms其中前面的 250ms 里 GPU 确实在密集跑 kernel剩下的 50ms 在等 CPU 喂数据。整个采样周期里 GPU 只“闲”了 50ms利用率算出来就是 83% 甚至更高但你恰恰需要关注的是那 50ms 的等待——因为只要把这 50ms 压缩掉训练速度直接提升六分之一。Trace 时间线把这个被压扁的信息重新展开了。它可以精确告诉你哪一个 kernel 之前出现了 20ms 的空白、哪一次显存拷贝阻塞了流水线、哪一个item()调用触发了一次全局同步。这些信息在nvidia-smi里统统看不到。所以我常说一句话利用率是给监控系统看的状态灯Trace 才是给工程师用的手术刀。3. Trace 时间线里的四重病灶空转的 GPU 都在等谁我排查过不少“利用率高但训练慢”的案例把 Trace 时间线拉出来之后发现导致问题的主因翻来覆去就是那么几类。这里我把它们总结成四重病灶每一重都对应一种非常典型的时间线形态。3.1 病灶一H2D/D2H 搬运占据时间线GPU 在等数据上车第一种最常见的情况是时间线上反复出现大段的H2DHost to Device或D2HDevice to Host传输块GPU 的计算 kernel 被这些搬运块硬生生隔开。数据从 CPU 内存搬到 GPU 显存走的是 PCIe 总线。即便 PCIe 4.0 x16 的理论带宽有 32GB/s跟 GPU 内部 HBM 显存动辄 1TB/s 以上的带宽比起来也差了不止一个数量级。换句话说搬数据的成本远比算数据高得多。如果你的训练循环每迭代一次都要把 input_ids、attention_mask、labels 从 CPU 拷贝到 GPU而且没做异步传输GPU 就只能在搬运期间干等着。这类问题在 Trace 上的典型长相是时间线上频繁出现紫色的传输块传输块之间夹着一些计算 kernel但两者没有重叠形成“传输——计算——传输——计算”的锯齿状结构。出现这类病灶的高发场景包括DataLoader 的 worker 在 CPU 侧做数据增强、动态 padding 后的变长 batch、验证阶段频繁把 loss 或指标从 GPU 拷回 CPU。很多人在用 BERT 类模型做微调时都会踩中这个坑。解法通常分三步给 DataLoader 打开pin_memoryTrue把张量传输改成non_blockingTrue把能搬到 GPU 上做的数据预处理尽量搬到 GPU 上做例如把 padding 操作放在 GPU 侧完成最后是减少 D2H 拷贝的频率loss 和评估指标可以先累积在 GPU 上每隔几十个 step 再同步一次。3.2 病灶二Kernel Launch GapGPU 在等 CPU 发号施令第二种病灶在时间线上比第一种更隐蔽kernel 和 kernel 之间没有明显的传输块但中间就是有一段空白GPU 迟迟没有等到下一个 kernel 被启动。这个空白的专业叫法是 Launch Gap。它的根因在 CPU 侧GPU 执行 kernel 的速度远远快于 CPU 准备并下发 kernel 的速度。尤其是用 Python 写训练循环时解释器每解析一个算子、每做一次动态 shape 推理、每进入一个 Python 分支都会在 CPU 侧消耗时间。而这些时间里 GPU 没有新活可干只能空转。我在一个微调任务里亲眼见过这样的场景一个很小的自注意力模块里Python 层的逐算子调度让同一个迭代里启动了 55 个 kernel很多 kernel 本身的 GPU 执行时间只有 1-3 微秒但 CPU 启动下一个 kernel 花了几十微秒。这笔账算下来GPU 真正计算的时间不到总时长的 60%其余的 40% 都花在了等待发令枪上。解决 Launch Gap 的核心思路是“减少启动次数、放大单个 kernel 的粒度”。可以试试这几个方向一是用torch.compile做算子融合把多个小算子合并成一个大的编译 kernel二是固定输入的 shape避免动态 shape 触发的重编译和分支判断三是把 Python 层的循环下沉到张量操作里能向量化的绝不写 for四是在可以接受的情况下使用 CUDA Graph 预先捕获整个计算图让 GPU 按图执行彻底绕开逐算子启动的开销。3.3 病灶三隐式同步截断流水线一个 item() 打停一整轮计算第三种病灶在 Trace 上长得特别“冤枉”前面明明跑得好好的 kernel 流水线突然被一个看似无关的小操作打断然后时间线上出现一个很长的等待尾巴。这个罪魁祸首通常是隐式同步。所谓隐式同步就是你调用某个 API 时CUDA 为了保证数据一致性强制让 CPU 等待 GPU 执行完当前所有已提交的工作。最典型的触发器包括对 GPU 张量调用.item()、.cpu()、.numpy()或者用 Python 直接索引 GPU 张量的某个元素。这些操作的结果需要从显存拷回 CPU而要做到这一点GPU 上所有排队中的 kernel 必须先执行完于是流水线被瞬间截断。很多人的训练循环里都写过这样一行代码loss loss.item()目的是把 loss 取出来记录日志。如果每个 step 都这么干就等于每个 step 都强制同步一次。单次同步的损耗可能只有几毫秒但累计到成千上万个 step 里就是好几分钟甚至几十分钟的纯浪费。这类问题的修法很直接记录日志或做指标统计时不要每步都取设备上的标量。可以把 loss 累积在一个 GPU 张量变量里每 50 步或 100 步再统一同步、统一写入日志。同理TensorBoard 的add_scalar调用也尽量避免每步都传 GPU scalar可以先在 GPU 侧聚合好。还有一个容易被忽略的隐式同步来源是显存分配。PyTorch 的 CachingAllocator 会缓存已释放的显存块但如果你的代码里不断创建新的、大小不固定的临时张量缓存命中率下降就可能触发真正的cudaMalloc。cudaMalloc本身是一个昂贵的设备同步操作一旦触发时间线就会出现一个长停顿。可以用torch.cuda.memory_reserved和torch.cuda.memory_allocated检查缓存与分配差值如果差值持续偏大就要检查代码里是不是有动态 shape 导致缓存碎片化了。3.4 病灶四Stream 串行与多卡通信等待算得动却合不拢第四种病灶分两种情况单卡和多卡。单卡情况下主要问题是所有操作默认跑在同一个 CUDA Stream 上Stream 内部的 kernel 严格按提交顺序串行执行即使两个 kernel 之间没有数据依赖也无法重叠。这样一来数据搬运、计算、甚至一些本可以并行的小任务都被排成了一条队。虽然 GPU 一直在忙但忙得毫无重叠度。解法是引入独立的非阻塞流把数据加载和 H2D 拷贝放到一个单独的 Stream 上计算放在主计算流上通过 CUDA event 做必要的依赖控制让数据搬运和上一轮计算在时间上重叠起来。这一步对吞吐的提升往往非常明显。多卡情况下问题焦点通常会转移到 NCCL 通信上。数据并行训练里每步结束后都需要对梯度做 AllReduce。如果通信时间和反向计算没有重叠好Trace 时间线上就会出现一条细长的通信阻塞带两侧的 kernel 都在等它完成。很多人在多卡训练里遇到“利用率高但扩展性差”的情况本质上就是通信等待吃掉了并行红利。排查方向包括确认 DDP 的梯度分桶配置是否合理、通信是否和反向传播重叠、有没有使用更高效的通信后端、单卡 batch size 是否过小导致通信占比过高。还有一个实用经验在 Trace 里专门看nccl相关的活动如果它们的平均耗时占比超过 20%就要认真考虑通信优化了。3.5 一张表快速定位时间线模式下四重病灶识别要点为了让你拿到 Trace 后能快速对号入座我把四种病灶在时间线上的特征整理成了下面这张表病灶类型Trace 上的典型形态最常见诱因优先对策H2D/D2H 搬运阻塞紫色传输块频繁出现计算 kernel 被隔断每次迭代拷贝输入、动态 padding、频繁 D2Hpin_memory non_blocking预处理搬上 GPUKernel Launch Gapkernel 之间出现大量空白GPU 时间线稀疏Python 逐算子启动、小 kernel 过多、动态 shapetorch.compile、固定 shape、CUDA Graph隐式同步流水线整齐运行中突然出现长等待尾巴.item()、.cpu()、.numpy()、cudaMalloc延迟同步、GPU 侧累积指标、检查显存缓存命中Stream 串行与通信等待单卡无重叠、多卡 NCCL 阻塞带明显默认流串行、梯度同步不重叠多流并发、DDP 调优、通信压缩或调桶大小拿到 Trace 先看有没有这四种形态基本就能锁定 80% 的问题。4. PyTorch Profiler 性能体检实操从最小探针到报告判读4.1 最小可用 Profiler 配置跑通一次训练采集说了这么多原理总要落到实操上。下面这个配置是我在项目里最常使用的最小采集模板你可以直接抄走from torch.profiler import profile, ProfilerActivity, schedule def trace_handler(p): p.export_chrome_trace(./trace_step.json) print(p.key_averages().table( sort_byself_cuda_time_total, row_limit20 )) prof profile( activities[ProfilerActivity.CPU, ProfilerActivity.CUDA], scheduleschedule(wait2, warmup2, active3, repeat1), on_trace_readytrace_handler, record_shapesTrue, with_stackTrue, profile_memoryTrue, ) with prof: for step, batch in enumerate(dataloader): if step 10: break run_one_training_step(batch) prof.step()这里有几个参数需要解释一下不然你只是复制粘贴不明白背后的意图。wait2, warmup2, active3的含义是前 2 个 step 只跳过、不采集因为刚启动的 CUDA 上下文还有初始化开销接下来 2 个 step 做 warmup让缓存分配器、cuDNN autotune 等机制进入稳定状态最后 3 个 step 才真正记录数据。如果不做 warmup数据里会混入大量噪声你看到的时间分布可能是不准的。record_shapesTrue会记录每个算子输入张量的 shape这对定位动态 shape 问题很有帮助。with_stackTrue会带上 Python 调用栈一旦发现某个算子是热点你能直接追到是哪一行代码调用的。profile_memoryTrue会额外记录显存分配和释放的事件排查显存碎片时必开。注意一点profile_memoryTrue和with_stackTrue都会显著增加 profiler 自身开销所以只建议在定位问题时开启不要长时间挂在训练循环里。4.2 体检报告判读三个数字一眼看出 GPU 在等什么采集完成后p.key_averages().table()会输出一张算子级别的聚合表。这张表里的字段很多但排障时我最先看的只有三个数字第一是Self CUDA Time Total最大的算子。如果它占用的时间非常集中比如某个矩阵乘法的 GPU 耗时占了一多半那说明 GPU 的计算本身是健康的瓶颈可能在别处如果最大的算子也只有几毫秒而一个 step 总共要几百毫秒那说明时间根本没有花在“计算”上而是花在了搬运、等待或启动上。第二是 CPU Total 和 CUDA Total 的差值。如果一个算子在 CPU 侧耗费了 50ms但 GPU 侧只有 2ms就要警惕 Launch Gap 问题。这个差值越大说明 GPU 等 CPU 的情况越严重。第三是Memcpy HtoD和Memcpy DtoH的耗时占比。在聚合表里按self_cuda_time_total排序后如果传输类事件排进了前几名基本就可以确定数据搬运是主要瓶颈。除了表格我更推荐打开导出出的trace_step.json看时间线。把文件拖进chrome://tracing或者perfetto放大看一个 step 的整体布局先看有没有大段空白再看空白前面是什么事件、后面是什么事件。这套阅读逻辑比盯着聚合表更符合人脑的直觉。4.3 三个容易误诊的地方我看 trace 时踩过的坑第一千万不要开CUDA_LAUNCH_BLOCKING1去分析性能。这个环境变量的作用是让每个 CUDA kernel 同步启动、同步等待它本来是定位非法内存访问等 bug 用的。如果在开它的情况下做性能分析所有异步执行和流水线重叠都会被强制变成串行Trace 时间线看起来一片都是空白你会得出“这代码慢死了”的错误结论。第二profiler 自身是有开销的。CUPTI 回调、事件缓冲区的读取、时间线的记录都会让训练比正常情况慢 5%-10%。所以优化前后对比时要用同一种测量方式做多次取中位数而不是拿一次带 profiler 的数据和一次不带 profiler 的数据直接对比。第三trace 文件可能会大得离谱。开启record_shapes、with_stack和多卡 profiling 后几秒钟的采集就能生成几百 MB 甚至 GB 级的 JSON。普通浏览器直接打开会卡死。我的习惯是先只跑 2-3 个 active step再开 Chrome 或者 perfetto 去加载。真要分析大文件时建议先用脚本过滤掉耗时极短的小 kernel只保留影响格局的大事件。5. 一次真实优化实录从一个“很忙”的微调任务到 step 耗时降三成5.1 初检trace 拉开后四个时间块让根因无处可藏理论讲得再多不如看一个完整的案例。有一回我在 A100 上微调一个中文 BERT 规模的模型batch size 64、序列长度 256。表面看显卡利用率 99%但每个 step 要跑 340ms 左右明显背离我们的预期。按照前面说的流程我给训练循环加上了 Profiler跑了几个 step 后导出 trace逐段放大看时间线。结果四个问题非常清楚地浮了出来。首先是时间线开头的位置每个 step 都有三次 H2D 拷贝分别拷贝 input_ids、attention_mask 和 labels。虽然单次数据量只有约 32KB理论上传输耗时极短但因为这些拷贝没有和上一轮计算重叠GPU 必须空转等待数据就位再开始新一步的前向传播。其次是 kernel 之间的 Launch Gap。时间线上计算 kernel 的颗粒度非常细碎很多只有 1-3 微秒级别的小算子被零散地提交CPU 启动它们的开销远大于 GPU 执行它们的开销。我数了一下一个 step 里这类小 kernel 有 50 多个累计造成的空白时间非常可观。第三个问题是隐式同步。训练循环里为了写日志每个 step 都执行了一次loss.item()。这一步操作把前面所有异步执行的 kernel 全部强制同步了一次时间线上能明显看到同步等待的尾巴。第四个问题在单卡场景下不算特别严重但依然存在所有操作都跑在默认流上数据搬运和计算没有任何重叠Stream 的串行化放大了前三个问题的效果。把这个 trace 看完之后我心里对性能账单有了一个大致估算数据搬运占掉约 30% 开销Launch Gap 占掉约 40%隐式同步占掉约 10%剩下 20% 是兜底和计算本身的开销。方向已经很明确了。5.2 改动是怎么落地的以及优化后的对比针对这四个问题我做了这样几处改动。数据搬运方面DataLoader 打开了pin_memoryTrue前向传入张量时使用non_blockingTrue同时把 tokenizer 的 padding 操作从 CPU 搬到了 GPU 上让数据预处理和上一轮计算尽量重叠。Launch Gap 方面我没有一上来就上torch.compile而是先把模型里几个把小算子拆开写的模块手动合并了又固定了所有输入张量的 shape。跑通后再开torch.compile把剩余融合空间交给编译器处理。隐式同步方面把训练循环里的loss.item()从每步调用改成了每 50 步调用一次中间的 loss 数值累积在 GPU 张量变量上只在需要写日志时同步一次。Stream 串行方面我单独创建了一条非阻塞流来做 prefetch让下一批数据的 H2D 拷贝和当前 step 的反向传播在时间上重叠。这个改动单独看来效果没那么夸张但它把前面三个优化释放出的空隙填满了属于压轴的临门一脚。优化后我用同样的方式重新采集step 耗时从 340ms 降到了 217ms 左右降幅大约 36%。kernel 之间的空白比例明显减少硬件计数器里的 SM 活跃占比也提升了。作为参考这些数字只代表这一组特定配置下的量级感受不同模型、不同 CPU 性能下结果会有差异但排查的顺序和方法是通用的。我做 GPU 性能优化这些年最大的体会是看到利用率高别急着换卡先把 Trace 拉出来看一遍。很多人一遇到训练慢就怀疑算力不够结果换了新卡问题照旧。真正让训练变慢的往往就是时间线上那些看不见的空白、等待和同步。把 PyTorch Profiler 的用法练熟把 Trace 的阅读逻辑内化成习惯你会发现大部分性能问题在换硬件之前就能解决。如果你后续要做多卡训练也建议先把单卡的这份“体检”工作做扎实——单卡上暴露出来的问题在多卡里只会被通信放得更大早一点在 Trace 里看清它后面省下的时间远比你调试的那一个下午值钱。