25-如何profiling一次RL Step

profiling RLHF 系统时，第一步不是打开最重的 profiler，而是先把一轮 step 拆成可信的时间账。 把 RLHF 性能排查从“感觉哪里慢”变成可读的时间账：先用 timing_raw 拆开 gen、reward、logprob、update、sync，再用 profiler 深挖具 体窗口。读完能判断指标证明了什么、不能证明什么，也为下一篇吞吐瓶颈分析打基础

第 24 篇把训练权重同步回 rollout，补上了 update_actor -> update_weights -> next rollout的闭环。闭环之后，最常见的问题会从“这套系统能不能跑通”变成“为什么这一轮这么慢”。如果只看 GPU 利用率，容易把问题误判为训练后端；如果只看 rollout 延迟，又可能忽略 old logprob、reward、actor update 或权重同步。第 25 篇要做的是建立一套读账方法：先用 verl 自己的 timing 还原 step 结构，再用硬件 profiler 深挖具体窗口。

本文的核心判断是：一次 RL step 的 profiling 应该分两层读。第一层是 timing_raw这张轻量账本，它把 gen、reward、old_log_prob、update_actor、update_weights等阶段落成 timing_s/*和 throughput 指标；第二层是 global_profiler.steps触发的 worker/rollout profiler，它只在选定 step 上回答更细的 kernel、operator、memory 或 trace 问题。前者负责定位窗口，后者负责解释窗口内部。

先看第 25 篇要建立的全局视角。读图时注意两点：第一，step是 trainer 主循环里的外层计时，内部阶段并不等价于同一类工作；第二，validation、profile start/stop、agent loop slowest metrics 也会进入同一份日志，但它们和核心训练阶段的含义不同。

一轮 RL step 的 profiling 账本

这张图给出本文的阅读路线：先定位 timing_s/step与主要阶段，再看 gen里 agent loop 的长尾信息，接着判断是否需要开启硬 profiler，最后把时间、token 和吞吐指标放在同一张表里解释。这样做的目的不是一次性找到唯一瓶颈，而是避免在证据不足时把慢点归因给错误模块。

1. marked_timer把 step 拆成可读账本

verl 的 PPO 主循环从 timing_raw = {}开始，然后用 marked_timer("step")包住一轮核心训练路径。marked_timer()的底层会进入 _timer()，用 Timer记录耗时，并把同名阶段累加到 timing_raw[name]。如果环境里有 NVTX 或 NPU marker，marked_timer()还会同时把同名范围标进硬件 trace；如果没有，它仍然会保留普通 stopwatch 语义。

下面这张图只画 trainer 里的时间账。读图时注意：step是外层总账，gen、reward、old_log_prob、adv、update_actor、update_weights是内部明细；有些明细只有在对应配置打开时才会出现。

trainer 主循环中的 timing_raw 明细

源码上，RayPPOTrainer.fit()在每个 batch 开始时创建 metrics和 timing_raw，随后按运行顺序写入 gen、reward、old_log_prob、Role.RefPolicy、values、adv、update_critic、update_actor、save_checkpoint、update_weights和 testing等阶段（verl/trainer/ppo/ray_trainer.py:1334-1642）。这个顺序很重要：它说明 profiling 不是事后把日志拼起来，而是训练循环本身定义了“哪些阶段值得单独计时”。

读这张账时要先分清“阶段存在”和“阶段耗时”两件事。ref只有启用 reference policy 才会计时；values与 update_critic依赖 critic；old_log_prob在 rollout correction bypass mode 下会被跳过重算；save_checkpoint只在保存条件满足时出现。也就是说，缺少某个 timing_s/*不一定是日志坏了，可能是配置分支没有走到。

2. gen要继续拆到 agent loop 的慢样本

gen是 RLHF 系统最容易被误读的阶段。外层 marked_timer("gen")包住 async_rollout_manager.generate_sequences()，随后 trainer 会让 checkpoint manager sleep rollout replicas，并把 combined_gen_output.meta_info["timing"]合并进 timing_raw。这意味着 timing_s/gen是 trainer 看到的生成窗口，而 agent loop 还会提供更细的 min/max/mean 和 slowest 信息。

下面这张图把 gen的两层时间放在一起。读图时注意：trainer 外层只知道“等 rollout 返回用了多久”；agent loop manager 会把每个样本的 generation、tool call、score 时间聚合成 min/max/mean，并标出最慢样本。

gen 阶段里的 agent loop timing

这张图解释了为什么 timing_s/gen不能直接等同于推理 engine 的纯生成性能。单轮 agent loop 会用 simple_timer("generate_sequences")包住 server request；tool agent loop 还会分别计 generate_sequences和 tool_calls；异步 reward loop 会给 compute_score计时。AgentLoopManager._performance_metrics()再把这些样本级指标聚合成 agent_loop/generate_sequences/min|max|mean、agent_loop/tool_calls/min|max|mean、agent_loop/compute_score/min|max|mean，并记录 slowest sample 的 prompt/response length（verl/experimental/agent_loop/single_turn_agent_loop.py:57-70，verl/experimental/agent_loop/tool_agent_loop.py:216-285，verl/experimental/agent_loop/agent_loop.py:806-868、1069-1126）。

因此，排查 gen慢时应该先看两类证据是否一致。如果 timing_s/gen高，同时 agent_loop/generate_sequences/max或 agent_loop/slowest/response_length高，问题更像是 rollout 长尾；如果 tool_calls/max或 compute_score/max高，慢点可能在工具或异步 reward；如果 agent loop 内部指标不高，但 gen高，就要继续查 controller、Ray 调度、sleep/resume 或输出合并。

3. reward、old_log_prob、update和 sync是不同问题

生成结束后，trainer 会把 rollout 结果合回 batch，计算 response mask、balance batch，并填充 global_token_num。后面的阶段看起来都在“训练侧”，但它们对应的系统问题完全不同：reward是奖励来源和提取成本；old_log_prob是 actor inference 或 rollout correction 的锚点；adv是 driver 上的优势计算；update_actor是训练后端的 forward/backward/optimizer；update_weights是训练权重回到 rollout 的同步。

下面这张图把这些阶段按“它回答什么问题”重新分组。读图时注意，不要把 old_log_prob、update_actor和 update_weights混成一个训练耗时，它们分别落在推理重算、训练更新和 train/serve 同步边界。

不同 timing 阶段回答不同系统问题

源码顺序能帮助我们控制归因。reward只在需要时调用 reward model 并提取 reward tensor；old_log_prob调_compute_old_log_prob()并记录perf/mfu/actor_infer；adv在 driver 上应用 KL、rollout correction 和 advantage estimator；update_actor调_update_actor()并把 worker 返回的 actor metrics 合进日志；update_weights调 checkpoint manager 把新 actor 权重送回 rollout（verl/trainer/ppo/ray_trainer.py:1426-1586）。如果timing_s/update_actor高，下一步应该进入训练 engine、micro-batch 和 MFU；如果timing_s/update_weights高，下一步应该看 checkpoint engine 后端、bucket、KV cache 和 abort/resume；如果timing_s/old_log_prob高，则更接近 actor inference 路径，而不是 optimizer update。

这里还有一个边界：timing_s/step和各阶段明细不一定能严格相加成完全一致的数字。原因包括嵌套计时、条件阶段、外层 Python/Ray 开销、validation 在 step外部计时、以及 rollout 内部 timing 合并。正确读法是用它们定位主要窗口，而不是做会计式闭合。

4. 硬 profiler 只应该在选定 step 深挖

轻量 timing 每一步都能记录，但硬 profiler 不应该无差别常开。verl 用 global_profiler.steps控制要 profile 的 step；如果配置了这些 step，trainer 创建 worker group 时会把 profile_steps传给 Ray worker group，使用 nsys 时还要求 worker_nsight_options。训练循环开始时 _start_profiling()会触发 actor/rollout、ref、critic worker group；结束时 _stop_profiling()关闭它们。

下面这张图画的是 profiler 控制面。读图时注意：worker profiler 和 rollout server profiler 是两条线；前者通过 worker group start/stop，后者在 gen阶段让 LLM server manager 对 replicas 发 start/stop。

global_profiler 控制 worker 和 rollout profiler

这个控制面说明硬 profiler 的定位应该服务于第一层 timing。如果 timing_s/update_actor高，可以在对应 step 打开 actor worker 的 torch/nsys/npu profiler；如果 timing_s/gen高，可以让 LLM server manager 在 gen窗口启动 rollout engine profiler；如果问题只出现在连续几个 step，profile_continuous_steps决定这些连续 step 是否合到一个 profile 数据库里（verl/trainer/config/ppo_trainer.yaml:200-230，verl/trainer/ppo/ray_trainer.py:760-770、1022-1038、1322-1342、1603-1615，verl/workers/rollout/llm_server.py:364-372）。

worker 侧还有 rank 过滤。DistProfiler会根据 enable、all_ranks、ranks判断当前 rank 是否参与 profile；没有显式 ranks 时，enabled profiler 默认只 profile rank 0。TrainingWorker与 ActorRolloutRefWorker都用 DistProfilerExtension注册 start_profile()和 stop_profile()，由 controller 一次性分发到所有 worker，再在本地决定是否真正启动（verl/utils/profiler/profile.py:72-162、290-315，verl/workers/engine_workers.py:121-129、471-485）。

5. metrics 把时间转成 token 视角

最后一步是把 timing_raw变成可对比的指标。compute_timing_metrics()会把每个原始阶段输出成 timing_s/{name}；同时，它只给一部分阶段计算 per-token 时间：gen按 response tokens 归一化，ref、values、adv、update_critic、update_actor按 prompt+response tokens 归一化。old_log_prob、reward、update_weights这类阶段会保留 raw seconds，但不会自动生成 per-token 指标。

下面这张图把派生关系画出来。读图时注意：throughput 用的是整步时间和总 token 数；per-token timing 则依赖阶段自己的 token 分母。二者都是有用指标，但回答的问题不同。

timing_raw 如何变成 timing 和 throughput metrics

compute_throughout_metrics()使用 batch.meta_info["global_token_num"]求总 token，再用 timing_raw["step"]和 GPU 数计算 perf/throughput = total_tokens / (step_time * n_gpus)（verl/trainer/ppo/metric_utils.py:271-346）。这给了一个端到端归一化指标，但它并不能告诉你瓶颈在哪里。比如 throughput 下降可能来自 response 变长、rollout 长尾、actor update 变慢、checkpoint 保存触发，或权重同步时间变大；必须回到 timing_s/*明细和配置分支继续拆。

所以一套实用读法是：

1. 先看 perf/time_per_step和 perf/throughput，确认端到端是否退化。
2. 再看 timing_s/gen、timing_s/old_log_prob、timing_s/update_actor、timing_s/update_weights谁贡献最大窗口。
3. 如果 gen异常，继续看 agent_loop/*/max和 slowest 样本；如果 update_actor异常，看 perf/mfu/actor、micro-batch 和训练 engine；如果 update_weights异常，看 checkpoint engine 后端和 rollout 状态。
4. 只有当窗口明确后，再用 global_profiler.steps在对应 step 打开 torch/nsys/npu/torch_memory profiler。

小结：profiling 的第一步是建立证据层级

第 25 篇没有直接回答“RLHF 吞吐瓶颈在哪里”，因为在不同模型、rollout 后端、reward 路径、sequence length 和 checkpoint engine 下，瓶颈会移动。它先建立一件更基础的事：一次 RL step 应该怎样被拆成证据层级。

放回系列地图，第 24 篇补完了权重同步闭环；第 25 篇开始进入 performance/scale/production system。读者现在应该能从 RayPPOTrainer.fit()的 timing_raw追到 compute_timing_metrics()、compute_throughout_metrics()和 global_profiler.steps，并知道每个指标能证明什么、不能证明什么。

下一篇第 26 篇会在这张账本上继续推进：当 gen、old_log_prob、update_actor、update_weights都能被单独观察以后，RLHF 吞吐瓶颈到底更常出现在 rollout generation，还是 actor update，或者二者之间的等待关系？

本文源码索引

• verl/utils/profiler/__init__.py:21-28：根据 NVTX/NPU 可用性选择 marked_timer()实现，否则回退到基础 performance timer。
• verl/utils/profiler/performance.py:140-195、verl/utils/profiler/nvtx_profile.py:84-111：marked_timer()如何写入 timing_raw，并在 NVTX 路径增加 marker。
• verl/trainer/ppo/ray_trainer.py:760-770：global_profiler.steps如何进入 worker group 创建参数，nsys 路径为什么需要 worker nsight options。
• verl/trainer/ppo/ray_trainer.py:1022-1038：trainer 如何统一 start/stop actor/rollout、ref 和 critic worker group profiler。
• verl/trainer/ppo/ray_trainer.py:1322-1642：一轮 PPO step 如何创建 timing_raw，拆出 gen、reward、old_log_prob、adv、update_actor、update_weights等阶段，并生成 metrics。
• verl/experimental/agent_loop/single_turn_agent_loop.py:57-70、verl/experimental/agent_loop/tool_agent_loop.py:216-285、verl/experimental/agent_loop/agent_loop.py:806-868、1069-1126：agent loop 如何记录 generation、tool call、compute score 和 slowest 样本 timing。
• verl/trainer/ppo/metric_utils.py:271-346：timing_raw如何转成 timing_s/*、timing_per_token_ms/*和 perf/throughput。
• verl/utils/profiler/profile.py:72-162、290-315：DistProfiler的 tool dispatch、rank 过滤和 worker start/stop 注册。
• verl/workers/engine_workers.py:121-129、471-485：TrainingWorker 与 ActorRolloutRefWorker 如何接入 DistProfilerExtension。
• verl/workers/rollout/llm_server.py:364-372、verl/workers/rollout/replica.py:293-299、verl/workers/rollout/vllm_rollout/vllm_async_server.py:624-638：rollout server profiler 如何在 replicas 和 vLLM async server 上启动/停止。