已关闭

[Bug-Report|缺陷反馈]: SFT训练qwen2.5vl出现NPU利用率变为0的现象然后超时 #143

gcw_rDAWYhIV创建于 2025年10月20日关闭于 2025年12月10日

2025年10月20日创建

Thanks for sending an issue! Please fill in the following template to help quickly solve your problem.

Describe the current behavior / 问题描述 (Mandatory / 必填)

基于Qwen2.5-vl-7b在视频数据集上做sft时，出现过几个step后，NPU利用率突然全部变为0的情况，且没有任何报错信息；卡住一段时间到达timeout设定值后退出。

Environment / 环境信息 (Mandatory / 必填)

CANN 8.2RC1
torch_npu=2.5.1

Steps to reproduce the issue / 重现步骤 (Mandatory / 必填)

启动脚本如下：
#!/bin/bash

该变量只用于规避megatron对其校验，对npu无效

export CUDA_DEVICE_MAX_CONNECTIONS=1
export ASCEND_SLOG_PRINT_TO_STDOUT=0
export ASCEND_GLOBAL_LOG_LEVEL=3
export TASK_QUEUE_ENABLE=2
export COMBINED_ENABLE=1
export CPU_AFFINITY_CONF=1
export HCCL_CONNECT_TIMEOUT=1200
export NPU_ASD_ENABLE=0
export ASCEND_LAUNCH_BLOCKING=0
export ACLNN_CACHE_LIMIT=100000

NPROC_PER_NODE=16
MASTER_ADDR=localhost
MASTER_PORT=6000
NNODES=1
NODE_RANK=0

NPUS_PER_NODE= $NPROC_PER_NODE MASTER_ADDR=$ MASTER_ADDR
MASTER_PORT= $MASTER_PORT NNODES=$ NNODES
NODE_RANK= $NODE_RANK WORLD_SIZE=$ (( $NPROC_PER_NODE*$ NNODES))

MM_DATA="./train/configs/data/sft_7b.json"
MM_MODEL="./train/configs/model/sft_7b_pp2.json"
MM_TOOL="./mindspeed_mm/tools/tools.json"
LOAD_PATH="./ckpt/mm_path/Qwen2.5-VL-7B-Instruct/tp2_pp2"
SAVE_PATH="./output/sft/"

TP=2
PP=2
CP=2
MBS=1

DP= $(($ WORLD_SIZE/ $TP/$ PP/ $CP)) GBS=128 GRAD_ACC_STEP=$ (( $GBS/$ MBS/$DP))

DISTRIBUTED_ARGS="
--nproc_per_node $NPUS_PER_NODE
--nnodes $NNODES
--node_rank $NODE_RANK
--master_addr $MASTER_ADDR
--master_port $MASTER_PORT
"

GPT_ARGS="
--use-mcore-models
--tensor-model-parallel-size ${TP}
--pipeline-model-parallel-size ${PP}
--context-parallel-size ${CP}
--context-parallel-algo megatron_cp_algo
--micro-batch-size ${MBS}
--global-batch-size ${GBS}
--tokenizer-type NullTokenizer
--tokenizer-name-or-path ./ckpt/hf_path/Qwen2.5-VL-7B-Instruct_thinking
--vocab-size 152064
--seq-length 32000
--make-vocab-size-divisible-by 1
--normalization RMSNorm
--use-fused-rmsnorm
--swiglu
--use-fused-swiglu
--no-masked-softmax-fusion
--lr 1.0e-5
--lr-decay-style cosine
--weight-decay 0
--train-iters 400
--lr-warmup-fraction 0.1
--clip-grad 0.0
--adam-beta1 0.9
--adam-beta2 0.999
--seed 42
--bf16
--load $LOAD_PATH
--use-flash-attn
--variable-seq-lengths
--use-distributed-optimizer
--num-workers 8
"

MM_ARGS="
--mm-data $MM_DATA
--mm-model $MM_MODEL
--mm-tool $MM_TOOL
"

OUTPUT_ARGS="
--log-interval 1
--save-interval 20
--eval-interval 10000
--eval-iters 5000
--save $SAVE_PATH \ --ckpt-format torch \ " logfile=$ (date +%Y%m%d)$(date +%H%M%S)
mkdir -p logs
torchrun $DISTRIBUTED_ARGS pretrain_vlm.py
$GPT_ARGS
$MM_ARGS
$OUTPUT_ARGS
--distributed-backend nccl
2>&1 | tee logs/train${logfile}.log
chmod 440 logs/train_${logfile}.log
find $SAVE_PATH -type d -exec chmod 750 {} ;
find $SAVE_PATH -type f -exec chmod 640 {} \; STEP_TIME=`grep "elapsed time per iteration" logs/train_$ {logfile}.log | awk -F ':' '{print$5}' | awk -F '|' '{print$1}' | head -n 150 | tail -n 100 | awk '{sum+= $1} END {if (NR != 0) printf("%.1f",sum/NR)}'` SAMPLES_PER_SECOND=`awk 'BEGIN{printf "%.3f\n", '$ {GBS}'*1000/'${STEP_TIME}'}' echo "Elapsed Time Per iteration: $STEP_TIME" echo "Average Samples per Second: $SAMPLES_PER_SECOND" LOG_TOKENS_PER_SECOND=grep "tokens per sample" logs/train_ ${logfile}.log` if [ "$ LOG_TOKENS_PER_SECOND" ]; then
AVERAGE_TOKENS=grep "tokens per sample" logs/train_${logfile}.log | awk -F 'tokens per sample:' '{print$2}' | awk -F '|' '{print$1}' | head -n 150 | tail -n 100 | awk '{sum+=$1} END {if (NR != 0) printf("%.1f",sum/NR)}'
TOKENS_PER_SECOND=awk 'BEGIN{printf "%.3f\n", '${SAMPLES_PER_SECOND}'*'${AVERAGE_TOKENS}'}'
echo "Consumed Tokens per Second: $TOKENS_PER_SECOND"
fi

Describe the expected behavior / 预期结果 (Mandatory / 必填)

前面几个step正常运行，但到达一定step后（不一定是某个特定step），出现NPU利用全部降为0现象（没有OOM），然后报错

[rank10]:[E1020 10:46:13.349434773 ProcessGroupHCCL.cpp:673] [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=1396, OpType=ALLREDUCE, NumelIn=1, NumelOut=1, Timeout(ms)=600000) ran for 632472 milliseconds before timing out.
[rank10]:[E1020 10:46:13.349468101 ProcessGroupHCCL.cpp:749] Some HCCL operations have failed or timed out. Due to the asynchronous nature of ASCEND kernels, subsequent NPU operations might run on corrupted/incomplete data.
[rank10]:[E1020 10:46:13.349473073 ProcessGroupHCCL.cpp:755] To avoid data inconsistency, we are taking the entire process down.
[rank10]:[E1020 10:46:13.350490836 ProcessGroupHCCL.cpp:1604] [Rank 0] HCCL watchdog thread terminated with exception: [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=1396, OpType=ALLREDUCE, NumelIn=1, NumelOut=1, Timeout(ms)=600000) ran for 632472 milliseconds before timing out.
terminate called recursively
[rank8]:[E1020 10:46:13.369318128 ProcessGroupHCCL.cpp:673] [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=1396, OpType=ALLREDUCE, NumelIn=1, NumelOut=1, Timeout(ms)=600000) ran for 632492 milliseconds before timing out.
[rank8]:[E1020 10:46:13.369353478 ProcessGroupHCCL.cpp:749] Some HCCL operations have failed or timed out. Due to the asynchronous nature of ASCEND kernels, subsequent NPU operations might run on corrupted/incomplete data.
[rank8]:[E1020 10:46:13.369358407 ProcessGroupHCCL.cpp:755] To avoid data inconsistency, we are taking the entire process down.
[rank8]:[E1020 10:46:13.369389640 ProcessGroupHCCL.cpp:1604] [Rank 0] HCCL watchdog thread terminated with exception: [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=1396, OpType=ALLREDUCE, NumelIn=1, NumelOut=1, Timeout(ms)=600000) ran for 632492 milliseconds before timing out.
terminate called recursively
[rank8]:[E1020 10:46:13.369494318 ProcessGroupHCCL.cpp:673] [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=94896, OpType=ALLREDUCE, NumelIn=25962496, NumelOut=25962496, Timeout(ms)=600000) ran for 632489 milliseconds before timing out.
[rank8]:[E1020 10:46:13.369510120 ProcessGroupHCCL.cpp:749] Some HCCL operations have failed or timed out. Due to the asynchronous nature of ASCEND kernels, subsequent NPU operations might run on corrupted/incomplete data.
[rank8]:[E1020 10:46:13.369514516 ProcessGroupHCCL.cpp:755] To avoid data inconsistency, we are taking the entire process down.
[rank8]:[E1020 10:46:13.369537059 ProcessGroupHCCL.cpp:1604] [Rank 0] HCCL watchdog thread terminated with exception: [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=94896, OpType=ALLREDUCE, NumelIn=25962496, NumelOut=25962496, Timeout(ms)=600000) ran for 632489 milliseconds before timing out.
terminate called recursively
[rank10]:[E1020 10:46:13.372072013 ProcessGroupHCCL.cpp:673] [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=94896, OpType=ALLREDUCE, NumelIn=25962496, NumelOut=25962496, Timeout(ms)=600000) ran for 632492 milliseconds before timing out.
[rank10]:[E1020 10:46:13.372090492 ProcessGroupHCCL.cpp:749] Some HCCL operations have failed or timed out. Due to the asynchronous nature of ASCEND kernels, subsequent NPU operations might run on corrupted/incomplete data.
[rank10]:[E1020 10:46:13.372094618 ProcessGroupHCCL.cpp:755] To avoid data inconsistency, we are taking the entire process down.
[rank10]:[E1020 10:46:13.372118095 ProcessGroupHCCL.cpp:1604] [Rank 0] HCCL watchdog thread terminated with exception: [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=94896, OpType=ALLREDUCE, NumelIn=25962496, NumelOut=25962496, Timeout(ms)=600000) ran for 632492 milliseconds before timing out.
terminate called recursively
[ERROR] TBE Subprocess[task_distribute] raise error[], main process disappeared!
[rank9]:[E1020 10:46:13.452106936 ProcessGroupHCCL.cpp:673] [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=1396, OpType=ALLREDUCE, NumelIn=1, NumelOut=1, Timeout(ms)=600000) ran for 632575 milliseconds before timing out.
[rank9]:[E1020 10:46:13.452143117 ProcessGroupHCCL.cpp:749] Some HCCL operations have failed or timed out. Due to the asynchronous nature of ASCEND kernels, subsequent NPU operations might run on corrupted/incomplete data.
[rank9]:[E1020 10:46:13.452147803 ProcessGroupHCCL.cpp:755] To avoid data inconsistency, we are taking the entire process down.
[rank9]:[E1020 10:46:13.452185235 ProcessGroupHCCL.cpp:1604] [Rank 0] HCCL watchdog thread terminated with exception: [Rank 0] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=1396, OpType=ALLREDUCE, NumelIn=1, NumelOut=1, Timeout(ms)=600000) ran for 632575 milliseconds before timing out.
terminate called recursively
[rank9]:[E1020 10:46:13.452275977 ProcessGroupHCCL.cpp:673] [Rank 1] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=94896, OpType=ALLREDUCE, NumelIn=25962496, NumelOut=25962496, Timeout(ms)=600000) ran for 632572 milliseconds before timing out.
[rank9]:[E1020 10:46:13.452295655 ProcessGroupHCCL.cpp:749] Some HCCL operations have failed or timed out. Due to the asynchronous nature of ASCEND kernels, subsequent NPU operations might run on corrupted/incomplete data.
[rank9]:[E1020 10:46:13.452300191 ProcessGroupHCCL.cpp:755] To avoid data inconsistency, we are taking the entire process down.
[rank9]:[E1020 10:46:13.452325172 ProcessGroupHCCL.cpp:1604] [Rank 1] HCCL watchdog thread terminated with exception: [Rank 1] Watchdog caught collective operation timeout: WorkHCCL(SeqNum=94896, OpType=ALLREDUCE, NumelIn=25962496, NumelOut=25962496, Timeout(ms)=600000) ran for 632572 milliseconds before timing out.
terminate called recursively
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
//envs/mindspeed_mm/lib/python3.10/multiprocessing/resource_tracker.py:224: UserWarning: resource_tracker: There appear to be 30 leaked semaphore objects to clean up at shutdown
warnings.warn('resource_tracker: There appear to be %d '
W1020 10:46:42.370806 3698855 site-packages/torch/distributed/elastic/multiprocessing/api.py:916] Unable to shutdown process 3698981 via Signals.SIGTERM, forcefully exiting via Signals.SIGKILL
E1020 10:46:43.536505 3698855 site-packages/torch/distributed/elastic/multiprocessing/api.py:869] failed (exitcode: -6) local_rank: 12 (pid: 3698978) of binary: //envs/mindspeed_mm/bin/python3.1
Traceback (most recent call last):
File "//envs/mindspeed_mm/bin/torchrun", line 8, in
sys.exit(main())
File "//envs/mindspeed_mm/lib/python3.10/site-packages/torch/distributed/elastic/multiprocessing/errors/init.py", line 355, in wrapper
return f(*args, kwargs)
File "//envs/mindspeed_mm/lib/python3.10/site-packages/torch/distributed/run.py", line 919, in main
run(args)
File "//envs/mindspeed_mm/lib/python3.10/site-packages/torch/distributed/run.py", line 910, in run
elastic_launch(
File "//envs/mindspeed_mm/lib/python3.10/site-packages/torch/distributed/launcher/api.py", line 138, in call**
return launch_agent(self._config, self._entrypoint, list(args))
File "//envs/mindspeed_mm/lib/python3.10/site-packages/torch/distributed/launcher/api.py", line 269, in launch_agent
raise ChildFailedError(
torch.distributed.elastic.multiprocessing.errors.ChildFailedError:

pretrain_vlm.py FAILED

Failures:
[1]:
time : 2025-10-20_10:46:11
host : -worker-0
rank : 13 (local_rank: 13)
exitcode : -6 (pid: 3698979)
error_file: <N/A>
traceback : Signal 6 (SIGABRT) received by PID 3698979
[2]:
time : 2025-10-20_10:46:11
host : -worker-0
rank : 14 (local_rank: 14)
exitcode : -6 (pid: 3698980)
error_file: <N/A>
traceback : Signal 6 (SIGABRT) received by PID 3698980

Root Cause (first observed failure):
[0]:
time : 2025-10-20_10:46:11
host : -worker-0
rank : 12 (local_rank: 12)
exitcode : -6 (pid: 3698978)
error_file: <N/A>
traceback : Signal 6 (SIGABRT) received by PID 3698978

[ERROR] 2025-10-20-10:46:43 (PID:3698855, Device:-1, RankID:-1) ERR99999 UNKNOWN applicaiton exception

Special notes for this issue/备注 (Optional / 选填)

gcw_rDAWYhIV

2025年10月20日评论：

plog

d6557f87ff6c4f6b8747d007ed36d226.log

AZe_404成员

2025年10月21日评论：

感谢您使用Mindspeed-MM，我们将以最快的时间帮您解决问题

AZe_404成员

2025年10月21日评论：

根据您提供的plog日志未发现明显错误，建议查看一下单步训练时间，关注一下是否为保存权重的步数导致超过10min，另外可以在sh脚本中加入如下参数设置超时时长：
--distributed-timeout-minutes 120 \
export HCCL_CONNECT_TIMEOUT=7200

（注：看到您使用的torch版本为2.5.1，建议使用MM对应分支支持版本，如master支持torch2.6.0/2.7.1，其他版本因为充分验证，不能保证是否存在问题；同时建议检查驱动、CANN、PTA使用配套版本）

AZe_404成员

2025年10月21日 issue状态由 TODO 改变为 WIP

gcw_rDAWYhIV

2025年10月22日评论：

跟设置超时时间大小无关吧？
并非卡在保存权重的step；
更新torch版本为2.6.0仍然出现这个问题
如下所示，在某一步突然利用率全变为0，然后卡住

xuzhengchuang

2025年10月23日评论：

我跑qwen3vl的时候也遇到了类似的问题：https://gitcode.com/Ascend/MindSpeed-MM/issues/146

chenpeizhe成员

2025年11月6日评论：

您好，请问卡住时有关注过host内存吗，是不是内存满了

林

林明哲成员

2025年11月6日评论：

建议使用py-spy，提供一下hang住时刻各进程的python堆栈，协助定位

young256成员

2025年12月1日评论：

可以开启增加环境变量 export ASCEND_LAUNCH_BLOCKING=1
然后在出现hang（卡住）现象之后，然后执行下面指令：

npu-smi info | awk -F' *\\| *' '/^\| [0-9]+ +[0-9]+ +\|/ {print $3}' | xargs -I {} sh -c '
    echo "===== Stack trace for PID {} =====" | tee -a stack.txt;
    py-spy dump --pid {} | grep -A 1000 "Thread.*MainThread" | tee -a stack.txt 2>&1
'

会把所有进程调用堆栈位置输入到stack.txt并输出到控制台。再把堆栈展示出来看下问题。

hhhzhuyizhi成员

2025年12月10日评论：

您好，此issue已经超过一周没有更新，现先将本issue关闭，有问题，欢迎后续交流。

H hhhzhuyizhi成员

2025年12月10日 issue状态由 WIP 改变为 DONE

H hhhzhuyizhi成员

2025年12月10日关闭了 issue

Describe the current behavior / 问题描述 (Mandatory / 必填)

Environment / 环境信息 (Mandatory / 必填)

Steps to reproduce the issue / 重现步骤 (Mandatory / 必填)

该变量只用于规避megatron对其校验，对npu无效

Describe the expected behavior / 预期结果 (Mandatory / 必填)

Related log / screenshot / 日志 / 截图 (Mandatory / 必填)

pretrain_vlm.py FAILED

Root Cause (first observed failure): [0]: time : 2025-10-20_10:46:11 host : -worker-0 rank : 12 (local_rank: 12) exitcode : -6 (pid: 3698978) error_file: <N/A> traceback : Signal 6 (SIGABRT) received by PID 3698978

Special notes for this issue/备注 (Optional / 选填)

Root Cause (first observed failure):
[0]:
time : 2025-10-20_10:46:11
host : -worker-0
rank : 12 (local_rank: 12)
exitcode : -6 (pid: 3698978)
error_file: <N/A>
traceback : Signal 6 (SIGABRT) received by PID 3698978