[training_utils] fix: Fix total train_time in sft_trainer.py and add 1) step time 2) seq len stats for training data.

[sheilaliuxl]

What does this PR do?

For SFT in sft_trainer.py:

1. Fix total train_time
2. Add more metrics
   1. step time
   2. train data seq len stats (count, min, max, mean, std, median)

Checklist Before Starting

• Search for similar PRs. Paste at least one query link here: https://github.com/verl-project/verl/pulls?q=is%3Apr+is%3Aopen+train_time
• Format the PR title as [{modules}] {type}: {description} (This will be checked by the CI)
  • {modules} include fsdp, megatron, veomni, sglang, vllm, rollout, trainer, ci, training_utils, recipe, hardware, deployment, ray, worker, single_controller, misc, perf, model, algo, env, tool, ckpt, doc, data, cfg, reward, fully_async, one_step_off
  • If this PR involves multiple modules, separate them with , like [megatron, fsdp, doc]
  • {type} is in feat, fix, refactor, chore, test
  • If this PR breaks any API (CLI arguments, config, function signature, etc.), add [BREAKING] to the beginning of the title.
  • Example: [BREAKING][fsdp, megatron] feat: dynamic batching

Test

Fully tested E2E:

• Before PR: 87962
• After PR: 88091 with roughly the same mfu as before

+ python /fsx/ubuntu/users/sliuxl/tb.py --files '../*run-ft-0[01]-verl-x3*/events*' --metric '*'
2026-03-13 01:45:31,083 [tb.py:206] WARNING - Unknonw metric `*`!
2026-03-13 01:45:31,083 [tb.py:216] INFO -

[00/02] File ../verl_config_pbtxt-5d4ffd4f--87962-run-ft-00-verl-x3-j-01-seq04k-ns01-sp01-bs04-pad1--20260312.173823/events.out.tfevents.1773362434.ip-10-4-133-220.1001322.0:
2026-03-13 01:45:31,127 [tb.py:235] INFO - Set benchmark with index 0
2026-03-13 01:45:31,127 [tb.py:264] INFO - [220/233] : (avg (std), med) = (131070.986 [   0.000] (  9.651), 131072.000)  # train/global_tokens
2026-03-13 01:45:31,128 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.150 [   0.000] (  0.054),   0.140)  # train/grad_norm
2026-03-13 01:45:31,128 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.019 [   0.000] (  0.003),   0.019)  # train/loss
2026-03-13 01:45:31,128 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.000 [   0.000] (  0.000),   0.000)  # train/lr
2026-03-13 01:45:31,128 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.294 [   0.000] (  0.007),   0.295)  # train/mfu
2026-03-13 01:45:31,128 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.016 [   0.000] (  0.008),   0.016)  # train/total_tokens(B)
2026-03-13 01:45:31,128 [tb.py:264] INFO - [00/01] : (avg (std), med) = (  0.000 [   0.000] (  0.000),   0.000)  # val/loss
2026-03-13 01:45:31,128 [tb.py:216] INFO -

[01/02] File ../verl_config_pbtxt-5d4ffd4f--88091-run-ft-01-verl-x3-j-01-seq04k-ns01-sp01-bs04-pad1--20260312.181925/events.out.tfevents.1773364884.ip-10-4-133-220.1008493.0:
2026-03-13 01:45:31,215 [tb.py:264] INFO - [220/233] : (avg (std), med) = ( 32.000 [x    nan] (  0.000),  32.000)  # data/train_seq_len_count
2026-03-13 01:45:31,215 [tb.py:264] INFO - [220/233] : (avg (std), med) = (4096.000 [x    nan] (  0.000), 4096.000)  # data/train_seq_len_max
2026-03-13 01:45:31,215 [tb.py:264] INFO - [220/233] : (avg (std), med) = (4095.968 [x    nan] (  0.302), 4096.000)  # data/train_seq_len_mean
2026-03-13 01:45:31,215 [tb.py:264] INFO - [220/233] : (avg (std), med) = (4096.000 [x    nan] (  0.000), 4096.000)  # data/train_seq_len_median
2026-03-13 01:45:31,216 [tb.py:264] INFO - [220/233] : (avg (std), med) = (4094.986 [x    nan] (  9.651), 4096.000)  # data/train_seq_len_min
2026-03-13 01:45:31,216 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.176 [x    nan] (  1.679),   0.000)  # data/train_seq_len_std
2026-03-13 01:45:31,216 [tb.py:264] INFO - [220/233] : (avg (std), med) = (131070.986 [   0.000] (  9.651), 131072.000)  # train/global_tokens
2026-03-13 01:45:31,216 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.150 [+  0.000] (  0.055),   0.140)  # train/grad_norm
2026-03-13 01:45:31,216 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.019 [-  0.000] (  0.003),   0.019)  # train/loss
2026-03-13 01:45:31,216 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.000 [   0.000] (  0.000),   0.000)  # train/lr
2026-03-13 01:45:31,217 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.295 [+  0.001] (  0.004),   0.296)  # train/mfu
2026-03-13 01:45:31,217 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  1.664 [x    nan] (  0.067),   1.643)  # train/time(s)
2026-03-13 01:45:31,217 [tb.py:264] INFO - [220/233] : (avg (std), med) = (  0.016 [   0.000] (  0.008),   0.016)  # train/total_tokens(B)
2026-03-13 01:45:31,217 [tb.py:264] INFO - [00/01] : (avg (std), med) = (  0.000 [   0.000] (  0.000),   0.000)  # val/loss

API and Usage Example

N.A.

Design & Code Changes

step_time can be more straightforward than mfu numbers, e.g. the latter has model TFLOPs vs hardware TFLOPs subtle differences.

Checklist Before Submitting

Important

Please check all the following items before requesting a review, otherwise the reviewer might deprioritize this PR for review.

• Read the Contribute Guide.
• Apply pre-commit checks: pre-commit install && pre-commit run --all-files --show-diff-on-failure --color=always
• Add / Update the documentation.
• Add unit or end-to-end test(s) to the CI workflow to cover all the code. If not feasible, explain why: ...
• Once your PR is ready for CI, send a message in the ci-request channel in the verl Slack workspace. (If not accessible, please try the Feishu group (飞书群).)
• If your PR is related to the recipe submodule, please also update the reference to the submodule commit via git submodule update --remote or cd recipe && git pull origin main.

[gemini-code-assist]

Code Review

This pull request correctly fixes the train_time accumulation and adds useful metrics for step time and sequence length statistics. The implementation is clear. I have one suggestion to improve the robustness of the sequence length statistics calculation by using more specific exception handling.