ARTICLE DETAIL

资讯详情

深耕编程入门与网站建设的一线实战洞察。

LLaMA-Factory训练日志监控实战:从日志解析到自动化告警

LLaMA-Factory训练日志监控实战:从日志解析到自动化告警 我敢说大部分用 llama-factory 跑微调的人都经历过这种类似看盘的状态命令敲下去训练一启动看着屏幕上滚动的日志就像看银行账户的数字流动赚了还是亏了全凭感觉。llama-factory 把大模型微调的门槛压得够低了但它自带的日志输出只能算能看离能监控还差得远。今天我把自己在 SFT、DPO、PT 这些任务上反复折腾出来的日志监控经验完整梳理一遍从日志文件在哪、字段怎么读到一条命令实时盯盘再给一个可以直接抄的 Python 监控脚本最后把高频故障的排查记录也一起放上来。这东西适合跑单机多卡、一次训练三五天甚至更久的朋友也适合刚接触 llama-factory 想搞清楚训练过程到底发生了什么的新手。1. 先搞清楚LLaMA-Factory 的日志到底从哪来、长什么样1.1 三种日志来源stdout、train_log.txt、TensorBoard我在排查问题时候的第一个教训就是别只盯一个日志源。llama-factory 跑起来之后实际上会有三套日志同时存在它们是互补的。第一套是标准输出也就是你用终端直接启动或者 nohup 重定向出来的那份。这套日志最全启动时的模型加载信息、数据集预处理、每一轮训练 loss、eval 结果、显存告警甚至底层 transformers 的警告全在里面。它的缺点是啰嗦一个训练跑到第三天这个文件可能已经几十 MB 甚至上 GB肉眼根本扫不过来。第二套是 llama-factory 自己维护的train_log.txt。只要你在正常用src/train_bash.py启动训练在output_dir目录下就会生成这个文件。它和标准输出不一样里面是工程化处理过的结构化记录通过框架内部的 LogCallback 把训练指标按固定格式写入。对于做监控来说这个文件价值最高因为格式稳定脚本好解析。第三套是可视化用的 TensorBoard 事件文件。这个不是默认开启的需要你在启动参数里给--report_to tensorboard或者在 WebUI 里勾选相应选项。它会在你指定的日志目录下生成 events 文件专门供 TensorBoard 渲染 loss 曲线、学习率曲线这些。你直接用tensorboard --logdir指向它就能看。这三套各有分工排查完整过程看 stdout做自动化监控看 train_log.txt给人看趋势用 TensorBoard。我见过不少人只 tail 一个 nohup.out然后其他两份日志完全不知道存在这就白白浪费了信息。1.2 一行训练日志里藏着哪些关键信息打开 train_log.txt你大概率会看到类似这样的行[INFO|callbacks.py:318] 2025-01-10 12:00:01,123 | epoch: 0.42 | step: 126 | loss: 1.2345 | lr: 2.0e-05 | grad_norm: 0.89如果用的是 transformers Trainer 的标准格式也可能是这种{loss: 1.2345, learning_rate: 2.0e-05, epoch: 0.42}这些不是乱码每一项都是训练健康度的关键信号。我把最重要的几个字段整理成了一张表监控脚本和肉眼盯盘其实都在关注这些东西字段含义危险信号loss当前步的平均损失突然出现 nan 或 inf比前几十步均值跳升 20% 以上learning_rate当前学习率预热阶段突变学习率被调度器重置回极高值epoch已经跑完多少个完整训练轮次长时间卡在同一个 epoch 值不动step全局步数长时间不增长说明训练可能死锁grad_norm梯度范数部分版本输出激增到正常量级几个数量级常伴随 loss 爆炸训练显存显存占用可能来自 nvidia-smi 助手脚本离显存上限很近下一轮 batch 就可能 OOM另外 stdout 里有一些需要盯的特殊字符串CUDA out of memory意味着显存爆了RuntimeError通常是代码层错误KeyboardInterrupt表示训练被手动中断early stopping或early_stopped表示触发了提前停止逻辑。这些字符串不一定出现在 train_log.txt 里必须靠监控脚本去扫 stdout 才能兜底。1.3 日志粒度怎么调才让监控有意义很多人的日志监控做不好不是因为不会 tail而是日志本身太稀疏或者太稠密。这里就涉及 llama-factory 的--logging_steps参数它决定每多少步记一条训练指标。这个参数怎么选我一般用一道简单的估算题来定。假设你有 1000 条训练样本per_device_train_batch_size是 2gradient_accumulation_steps是 8单卡训练。在不考虑梯度累积串联的情况下一个 step 实际吃掉的样本数是 2 × 8 16 条一个 epoch 大约就是 1000 / 16 ≈ 62.5 步取整后大约 63 步。如果你要跑 3 个 epoch总共约 189 步。这种量级logging_steps设 10 的话一个 epoch 才记 6 个点左右曲线会非常粗糙设 1 又太碎。我会直接设 1 到 5确保一个 epoch 能攒下至少十几个点。反过来如果你的数据量很大一个 epoch 有 5000 步那logging_steps设 50 到 100 更合理否则日志文件会膨胀得很快。还有一个容易被忽略的点save_steps会影响训练日志的节奏。llama-factory 每个 checkpoint 保存都会往日志里输出一段保存动作如果保存频繁日志里会穿插大量和训练指标无关的信息。我一般把save_steps和eval_steps按小时或按 epoch 维度来设而不是图省事随便填这样日志主题会干净很多。2. 为什么不能只靠肉眼盯日志监控方案怎么选2.1 裸跑训练的三个常见盲点第一进度条是瞬时的。llama-factory 底层用 tqdm 渲染进度条训练结束时它的历史记录就直接留在当前屏幕缓冲区里了。等训练跑完你想回头查 2 个小时前的 loss 到底是 1.23 还是 1.32你是翻不到的。第二重定向下 tqdm 行为异常。很多人习惯用nohup python ... train.log 21 启动训练问题在于 tqdm 写 stderr重定向后进度条会变成一坨一坨的转义字符把整个日志文件刷得没法看。更坑的是 Python 的 stdout 默认是全缓冲一旦进程非正常退出日志里可能只停留在好几分钟前的内容误导排查方向。第三没有阈值告警。肉眼盯盘只能发现已经出事的事比如 loss 变成 nan等你明天早上睡醒刷一眼日志才发现它从凌晨就开始爆了这台 GPU 白白跑了一晚上废功。这不是夸张我真的见过 8 卡机器一晚上跑出几万步废日志的情况。所以我的结论很直白日志监控不是帮你看训练跑得多快而是帮你在训练变坏的最早时刻知道它坏了。2.2 从轻到重的三档监控方案先别急着上 Prometheus 那一套我按成本从低到高分了三档你可以照着选。第一档是零依赖方案训练时把日志落盘然后用tail -f、grep、watch配合nvidia-smi做轮换查看。这套方案成本为零适合只跑几个小时的短任务人坐在机器前面盯着就行。第二档是脚本自动化方案写一个 Python 脚本定时解析 train_log.txt把关键指标解析成摘要检测到 nan、loss 突增、进程退出、日志长时间不更新等情况时通过 Webhook 发通知。这套方案只需要一台训练机和一个通知渠道做一次配置后面就能长期复用是我个人最推荐的一档。第三档是完整可观测性方案用 node_exporter nvidia_gpu_exporter 采集主机和 GPU 指标把指标推到 Prometheus再用 Grafana 出面板。这套方案适合多机、多卡、多人共用训练集群的场景它的优势是历史指标可回溯一屏看到所有机器的 GPU 利用率和训练曲线但运维成本确实高不是谁都需要一上来就搭它。监控方案依赖成本适合场景tail grep watch无零短任务、有人值守日志解析 WebhookPython Webhook低单机多卡、长训任务Prometheus Grafanaexporter 时序库中高多机集群、多人共用2.3 为什么我更推荐日志文件 轻量脚本这一档训练场景和 Web 服务不同它是一段长时间、高资源占用的单一进程。对于这种场景监控的重点不是每秒请求量而是训练指标是否在健康区间内。Prometheus 那套能解决资源维度的问题但它在loss 曲线是不是坏了这件事上并不擅长。你得再额外写 exporter 把训练指标暴露出来这就要侵入训练代码或者改 llama-factory 的启动逻辑复杂度和耦合度都上来了。而轻量脚本方案的好处恰好是零侵入。llama-factory 已经帮我们写好了 train_log.txt我只需要定时读这个文件做规则判断然后发通知。它不干扰训练进程也不需要额外装服务哪天不想用了直接删脚本就行。唯一需要考虑的是解析脚本怎么写才稳规则怎么定才不会误报。这部分我放到下一节完整展开。3. 实操搭一套能落地的日志监控链路3.1 启动命令规范化日志落盘和进程 PID 一次搞定我现在的标准启动命令是这样每次新建训练任务时直接套用export PYTHONUNBUFFERED1 export CUDA_VISIBLE_DEVICES0,1,2,3 TIMESTAMP$(date %Y%m%d_%H%M%S) mkdir -p logs nohup python src/train_bash.py \ --model_name_or_path meta-llama/Llama-3.2-1B \ --dataset alpaca_zh \ --finetuning_type lora \ --output_dir output/llama-sft \ --per_device_train_batch_size 2 \ --gradient_accumulation_steps 8 \ --learning_rate 2e-4 \ --num_train_epochs 3 \ --max_seq_length 1024 \ --logging_steps 5 \ --save_steps 500 \ --report_to tensorboard \ --logging_dir logs/tb_logs \ logs/sft_${TIMESTAMP}.log 21 echo $! logs/train.pid这里面有几个关键动作值得说一说。第一PYTHONUNBUFFERED1是必须的它让 Python 不缓冲标准输出日志能立刻落盘进程被 kill 时最后一刻的报错也能保住。第二标准输出和标准错误都重定向到同一个带时间戳的日志文件判定路径简单。第三进程 PID 写进logs/train.pid后面脚本判断进程存活、手动 kill 都方便。如果你不想丢掉控制台那份实时输出可以把改成21 | tee logs/sft_${TIMESTAMP}.log这样用 tee 同时输出到屏幕和文件。只不过在 nohup 后台模式下 tee 的语法需要写成管道形式注意区分否则日志路径容易和对不上。3.2 实时盯盘几组命令行组合技日志落盘之后实时盯盘其实靠几组命令就能很舒服地完成。最简单的就是tail -f但我建议配合grep做过滤tail -f logs/sft_*.log | grep --line-buffered -E loss|error|out of memory--line-buffered一定要加否则 grep 自己也会缓存输出你在终端看到的同样是延迟的。这样过滤之后屏幕上就只剩训练指标和真正的报错不会再被几千行无关信息刷屏。GPU 资源这边我习惯开第二个终端窗口用watch定时刷新watch -n 2 nvidia-smi --query-gpuindex,utilization.gpu,memory.used,memory.total --formatcsv对于单机多卡训练这组命令能直接看出四张卡的利用率是否均衡。如果某张卡长时间利用率为 0%多半是数据加载或者通信环节出了问题。另外你也可以用ls -l --time-style%H:%M:%S train_log.txt看一眼日志文件最后修改时间如果五分钟没变大概率训练卡住了这个时候不要急着看进程先看这个。3.3 可复用的 Python 监控脚本命令行盯盘只能解决人在现场的问题。真正省心的是写一个脚本放在后台跑每两分钟扫一次日志出了问题自动告警。下面这个脚本是我自己一直在用的简化版可以直接保存为watch_training_log.py使用。#!/usr/bin/env python3 import argparse import json import os import pickle import subprocess import sys import time import urllib.request from collections import deque from pathlib import Path def send_webhook(url, title, content): if not url: return payload { msgtype: text, text: {title: title, content: content, at_all: True}, } data json.dumps(payload).encode(utf-8) req urllib.request.Request(url, datadata, headers{Content-Type: application/json}) try: urllib.request.urlopen(req, timeout5) except Exception as exc: print(fwebhook send failed: {exc}) def check_nan_inf(value, path): if value ! value or value in (float(inf), float(-inf)): send_webhook(args.webhook, 训练数值异常, f{path} 出现 NaN/Inf: {value}) def check_loss_spike(loss, recent_losses, path): if len(recent_losses) 30: return base sum(recent_losses) / len(recent_losses) if base 0 and loss base * 1.5: send_webhook( args.webhook, Loss 突增, f{path} 当前 loss{loss:.4f}, 近30个点均值{base:.4f}, ) def main(): global args parser argparse.ArgumentParser() parser.add_argument(--log-file, requiredTrue, helptrain_log.txt or stdout log path) parser.add_argument(--pid-file, defaultlogs/train.pid, helpfile storing training pid) parser.add_argument(--interval, typeint, default60, helpcheck interval in seconds) parser.add_argument(--stall-minutes, typeint, default10, helpalert if log not updated) parser.add_argument(--webhook, default, helpwebhook url) args parser.parse_args() state_file /tmp/llama_factory_log_watch.pkl last_size 0 last_mtime time.time() recent_losses deque(maxlen50) while True: log_path Path(args.log_file) pid_alive False if args.pid_file and os.path.exists(args.pid_file): try: pid int(Path(args.pid_file).read_text().strip()) subprocess.run([kill, -0, str(pid)], checkFalse) pid_alive True except Exception: pid_alive False else: pid_alive True if not pid_alive: send_webhook(args.webhook, 训练进程退出, PID 不存在请登录服务器检查日志) sys.exit(1) if log_path.exists(): mtime log_path.stat().st_mtime if time.time() - mtime args.stall_minutes * 60: send_webhook(args.webhook, 训练可能卡死, 日志长时间未更新) size log_path.stat().st_size if size last_size: with open(log_path, r, encodingutf-8, errorsignore) as f: f.seek(last_size) new_lines f.readlines() last_size f.tell() for line in new_lines: if loss not in line.lower(): continue try: record json.loads(line.split(|, 1)[-1].strip()) except json.JSONDecodeError: continue loss record.get(loss) if loss is None or not isinstance(loss, (int, float)): continue check_nan_inf(loss, log_path) check_loss_spike(loss, recent_losses, log_path) recent_losses.append(loss) else: if not pid_alive: continue send_webhook(args.webhook, 日志文件缺失, train_log 不存在但训练进程仍在) time.sleep(args.interval) if __name__ __main__: main()这个脚本启动方式很简单nohup python watch_training_log.py \ --log-file output/llama-sft/train_log.txt \ --pid-file logs/train.pid \ --interval 60 \ --stall-minutes 10 \ --webhook https://your.webhook.url logs/monitor.log 21 脚本做的事情归纳起来就四件检查进程是否存活、检查日志文件是否还在更新、检查 loss 是否为 nan/inf、检查 loss 是否比近 50 个点均值暴增 50% 以上。后面两个是真正的训练预警可以用来避免晚上睡觉时 loss 已经崩了但没人知道的尴尬局面。实际使用中有几个小坑。第一train_log.txt的行格式在不同 ca 版本里可能有差异如果json.loads解析失败脚本会静默跳过所以不会因格式变动而崩溃但你也需要看一眼它是不是真的在解析出数据。第二脚本重启后是从文件当前尾部开始追踪的如果你想从零开始监控删掉 state 文件即可但通常不需要。第三Webhook 地址别在公开仓库里提交这个我就不多说了。3.4 配合 TensorBoard 看曲线脚本负责报警而看趋势这件事我用 TensorBoard 解决。llama-factory 启动时给了--report_to tensorboard --logging_dir logs/tb_logs训练开始后另开一个终端跑tensorboard --logdir logs/tb_logs --port 6006浏览器打开http://服务器IP:6006就能看到 loss 曲线、学习率曲线以及模型结构里的直方图。我一般重点看两条曲线第一条是 loss 曲线如果它是一条平滑下降后进入平台的曲线就是健康如果中间出现一个 V 型反弹或者突然拉高那通常踩到了学习率峰值或者数据问题。第二条是学习率曲线llama-factory 默认的 cosine 调度会在后期把学习率压得很低如果曲线不是平滑的那调度器很可能配置有问题。如果你是远程服务器跑训练本地浏览器看面板很卡可以加--bind_all再配访问控制或者干脆用 ssh 隧道转发端口过去我通常用后一种方式少暴露一个端口就少一份麻烦。4. 训练日志监控高频问题与排查实录4.1 日志卡住但 GPU 还在跑这个现象很迷惑人nvidia-smi显示 GPU 利用率 90% 以上但训练日志已经五分钟没更新了。第一次遇到这种问题我还以为训练卡死了直接杀了进程后来才知道这是经典坑。原因通常是 tqdm 进度条渲染与日志混写导致刷新异常或者是 Python 的 buffered 模式把输出暂存在内存里。解决手段有两条启动命令里一定要有PYTHONUNBUFFERED1或python -u另外--report_to尽量显式配置避免它默认去找 wandb 或别的 SDK 时卡在重试。如果已经卡了先别慌用strace -p PID看进程是不是在做 IO 等待或者直接看 train_log.txt 的 mtime如果 mtime 在动训练没死只是终端没刷出来。4.2 loss 突然变成 NaN 或 inf这个属于训练事故里最高发的一类。loss 变成 nan 之后如果不干预后面的训练步基本就是白跑甚至会把已经保存的 checkpoint 状态带坏。我遇到过的情况大概有三种。第一种是学习率开太大特别是刚开始训练那几百步loss 直接从个位数跳到 nan。这种解法是调低learning_rate或调小 warmup 比例。第二种是混合精度溢出fp16 训练时 loss 尺度太小模型结构又比较深梯度直接变成 inf。此时要么用--bf16配合支持 bf16 的卡要么把--fp16_opt_level调整得更保守。第三种是数据里本身有异常样本比如某些样本的长度极端、文本里嵌套了超长 token导致某个 batch 的特征数值炸掉这种可以配合日志监控里的 loss 突增规则定位到具体 step 再去查数据清洗逻辑。我在脚本里特意做了 nan 检测和 loss 突增检测就是为了把这种问题从事后翻日志变成事中即时告警。4.3 训练进程突然消失却没有报错进程没了但日志末尾看不到任何 Python traceback这种最让人抓狂。先说排查顺序先看进程存活时间再看系统日志。dmesg | tail -n 30如果看到Out of memory: Killed process之类的内容那就是被内核 OOM killer 干掉的。原因通常是宿主机的内存不足注意不只是显存llama-factory 加载数据集、缓存 checkpoints 都会吃系统内存多个进程叠加很容易把内存耗尽。解决方法是在启动前用free -g看一眼系统内存给--per_device_train_batch_size和--max_seq_length留出余量同时把save_steps调大减少偶发的内存峰值。如果 dmesg 里没有 OOM进程却没了可以检查是不是有人手动 kill 了或者 SSH 会话断掉后进程组被清理。这里我又要提那个教训一定要把 PID 写到文件里并且用setsid或nohup让进程脱离会话否则长训练任务半夜被某个断开的连接误杀后悔都来不及。4.4 多卡/多机日志混乱多卡训练时如果你是直接用torchrun --nproc_per_node4或者 llama-factory 的多卡启动方式每个 rank 都会尝试向 stdout 输出日志最终落盘时经常出现多个 rank 的日志交错在一起step 号对不上排查问题跟看悬疑剧本一样。我的处理原则是只认 rank 0 的输出。多卡启动命令里通常local_rank或RANK环境变量会自动注入rank 0 负责汇总训练指标其他 rank 主要负责计算和通信它们的日志里除了卡死报错外普通训练指标参考意义不大。具体的做法是启动前先判断环境变量rank 不为 0 就把标准输出全部丢弃只在 rank 0 上保留完整日志。自己写启动脚本的时候可以加一行if [ ${RANK:-0} -eq 0 ]; then exec python src/train_bash.py ... logs/train.log 21 else exec python src/train_bash.py ... /dev/null 21 fi这样日志文件里就只有 rank 0 的内容train_log.txt 里也就是一致的指标序列不会再出现步数跳跃的错觉。4.5 日志磁盘占用与轮转长时间训练最容易被忽视的问题就是磁盘被日志和 checkpoint 吃满。checkpoint 占空间大家都有感知日志文件反而是隐性炸弹。我见过一个训练任务跑了一周光 stdout 日志就写了 120GB最后把output_dir所在的盘填满了训练直接挂掉。推荐做法是日志目录单独放到一块容量充足的盘并且用 logrotate 按天分割日志。配置可以这么写/path/to/logs/train.log { daily rotate 30 compress delaycompress missingok notifempty copytruncate }copytruncate很关键因为训练进程一直持有文件句柄普通 truncate 可能导致训练进程日志写入出错copytruncate会在备份后截断原文件让训练进程无感。日志轮转对于后续做长期监控和故障溯源也很有价值因为你留的是时间切片而不是一个令人崩溃的巨型文件。4.6 日志作为长期审计依据最后想聊一个容易被低估的用法日志的长期留存。训练任务跑完不是终点模型上线之后如果出现效果异常训练日志就是唯一的客观事实来源。我在每个训练任务结束后会专门把train_log.txt、stdout 日志、TensorBoard 事件文件按日期归档到一个目录同时用一个哈希文件记录它们的完整性。什么时候会用到这些旧日志模型跑一段时间后效果变差你需要确认是不是训练阶段就已经埋下隐患数据集更新后复现实验结果你要对比同一模型在不同版本数据下的 loss 曲线或者排查谁在服务器上做了非预期操作日志里的启动时间、环境变量、命令行参数都会留下痕迹。这些都是监控二字的长期价值不只是为了训练期间盯着看一眼那么简单。我现在的固定流程很简单任何一次微调实验先把日志目录建好把监控脚本挂上把 Webhook 通道打开。真正让我放心的是训练出问题时机器会主动喊我而不是我第二天早上发现它已经悄悄跑偏了一整晚。如果你也在用 llama-factory 跑长任务别只盯着终端里的进度条把这套日志链路搭好睡个安稳觉是值得的。
返回列表