已关闭
[Usage]: Running profiling failed.Please check log for more info. #40
pyf创建于  4月13日关闭于  4月23日
pyf
4月13日 创建

在提交新问题之前,请确保您已经在社区中搜索过相关问题,并使用了社区中提供的资源/工具后,仍未找到满意的解决方式。

环境信息

例如:
- 操作系统
- 昇腾硬件信息
- CANN软件版本
- 安装的对应软件版本

openEuler
910B4
CANN8.5
torch 2.9.0
torch_npu 2.9.0

使用场景及问题

import sys
sys.path.insert(0, "/home/modelscope/Qwen3-VL-Reranker-2B")
from scripts.qwen3_vl_reranker import Qwen3VLReranker

# Specify the model path
model_name_or_path = "/home/modelscope/Qwen3-VL-Reranker-2B"

# Initialize the Qwen3VLEmbedder model
model = Qwen3VLReranker(model_name_or_path=model_name_or_path)
# We recommend enabling flash_attention_2 for better acceleration and memory saving,
# model = Qwen3VLReranker(model_name_or_path=model_name_or_path, torch_dtype=torch.bfloat16, attn_implementation="flash_attention_2")

# Combine queries and documents into a single input list

inputs = {
    "instruction": "Retrieve images or text relevant to the user's query.",
    "query": {"text": "A woman playing with her dog on a beach at sunset."},
    "documents": [
        {"text": "A woman shares a joyful moment with her golden retriever on a sun-drenched beach at sunset, as the dog offers its paw in a heartwarming display of companionship and trust."},
        # {"image": "https://qianwen-res.oss-cn-beijing.aliyuncs.com/Qwen-VL/assets/demo.jpeg"},
        # {"text": "A woman shares a joyful moment with her golden retriever on a sun-drenched beach at sunset, as the dog offers its paw in a heartwarming display of companionship and trust.", "image": "https://qianwen-res.oss-cn-beijing.aliyuncs.com/Qwen-VL/assets/demo.jpeg"}
    ],
    "fps": 1.0
}

scores = model.process(inputs)
print(scores)

使用msprof --output=output --application="python qwen3_vl_rerank_basic.py"启动,最后打印:
[ERROR] Running profiling failed.Please check log for more info.

打开调试信息后,

export ASCEND_SLOG_PRINT_TO_STDOUT=1(日志打屏环境变量)
export ASCEND_GLOBAL_LOG_LEVEL=0(日志级别改为debug模式环境变量),

报错如下:
image.png

请问这个问题要怎么解决呢?

由于全量的log无法上传,过滤了一下PROFILING的log

	Line    3: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.634.951 [params_adapter.cpp:240] >>> (tid:2336826) platformadapter init done.
	Line    4: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.000 [utils.cpp:547] >>> (tid:2336826) mmRealPath ret=0.
	Line    5: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.015 [utils.cpp:551] >>> (tid:2336826) Input path:output, canonicalized path:output
	Line    6: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.034 [utils.cpp:547] >>> (tid:2336826) mmRealPath ret=0.
	Line    7: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.045 [utils.cpp:551] >>> (tid:2336826) Input path:output, canonicalized path:output
	Line    8: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.072 [utils.cpp:547] >>> (tid:2336826) mmRealPath ret=0.
	Line    9: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.083 [utils.cpp:551] >>> (tid:2336826) Input path:output, canonicalized path:output
	Line   10: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.155 [platform_adapter_interface.cpp:89] >>> (tid:2336826) comParams.storageLimit:, dirFreeSize:1241368, params_->storageLimit:1241368MB
	Line   11: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.193 [msprof_manager.cpp:30] >>> (tid:2336826) init MsprofManager begin.
	Line   12: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.213 [msprof_manager.cpp:44] >>> (tid:2336826) init MsprofManager end.
	Line   13: [INFO] Start profiling...
	Line   14: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.254 [application.cpp:169] >>> (tid:2336826) Handle app_env param 
	Line   15: [INFO] PROFILING(2336826,msprof):2026-04-13-10:59:34.635.383 [utils.cpp:574] >>> (tid:2336826) Execute cmd:"python qwen3_vl_rerank_basic.py", stdoutRedirectFile=.
	Line  517: [INFO] PROFILING(2336827,python):2026-04-13-10:59:37.418.851 [prof_cann_plugin.cpp:289] (tid:2336827) Register module[48] callback.
	Line  519: [EVENT] PROFILING(2336827,python):2026-04-13-10:59:37.460.837 [msprof_callback_impl.cpp:383] >>> (tid:2336827) Started to register profiling ctrl callback.
	Line  520: [EVENT] PROFILING(2336827,python):2026-04-13-10:59:37.461.031 [msprof_callback_impl.cpp:390] >>> (tid:2336827) Started to register profiling hash id callback.
	Line  521: [INFO] PROFILING(2336827,python):2026-04-13-10:59:37.461.051 [prof_atls_plugin.cpp:117] (tid:2336827) RegisterProfileCallback, callback type is 7
	Line  522: [EVENT] PROFILING(2336827,python):2026-04-13-10:59:37.461.061 [msprof_callback_impl.cpp:397] >>> (tid:2336827) Started to register profiling enable host freq callback.
	Line  523: [INFO] PROFILING(2336827,python):2026-04-13-10:59:37.461.069 [prof_atls_plugin.cpp:117] (tid:2336827) RegisterProfileCallback, callback type is 8
	Line  524: [EVENT] PROFILING(2336827,python):2026-04-13-10:59:37.461.076 [msprof_callback_impl.cpp:404] >>> (tid:2336827) Started to register profiling typeId callback.
	Line  525: [INFO] PROFILING(2336827,python):2026-04-13-10:59:37.461.085 [prof_atls_plugin.cpp:117] (tid:2336827) RegisterProfileCallback, callback type is 6
	Line  526: [INFO] PROFILING(2336827,python):2026-04-13-10:59:37.461.091 [mstx_inject.cpp:383] >>> (tid:2336827) profiler registeMstxFunc to profcommon.so
	Line  527: [INFO] PROFILING(2336827,python):2026-04-13-10:59:37.461.461 [mstx_inject.cpp:363] >>> (tid:2336827) Succeed to get func table for module 1
	Line  528: [INFO] PROFILING(2336827,python):2026-04-13-10:59:37.461.480 [mstx_inject.cpp:363] >>> (tid:2336827) Succeed to get func table for module 2
	Line  900: [INFO] PROFILING(2336827,python):2026-04-13-10:59:37.500.248 [prof_atls_plugin.cpp:230] (tid:2336827) Module[48] register callback of ctrl handle.
	Line  923: [INFO] PROFILING(2336827,python):2026-04-13-10:59:37.514.335 [prof_atls_plugin.cpp:230] (tid:2336827) Module[48] register callback of ctrl handle.
	Line 2981: [INFO] PROFILING(2336827,python):2026-04-13-10:59:42.200.250 [prof_atls_plugin.cpp:230] (tid:2336827) Module[61] register callback of ctrl handle.
	Line 2988: [INFO] PROFILING(2336827,python):2026-04-13-10:59:42.205.561 [prof_atls_plugin.cpp:230] (tid:2336827) Module[0] register callback of ctrl handle.
	Line 2996: [2026-04-13 10:59:42.205505] [info] [2336827] [profiling_funcs.cpp:47] MsprofRegisterCallback start!
	Line 3726: [EVENT] PROFILING(2336826,msprof):2026-04-13-10:59:57.637.382 [running_mode.cpp:605] >>> (tid:2336826) App process 2336827 exited, exit code:0
	Line 3727: [WARNING] PROFILING(2336826,msprof):2026-04-13-10:59:57.637.526 [utils.cpp:166] >>> (tid:2336826) MsprofMmGetFileSize fail, ret=-1, errno=2.
	Line 3728: [ERROR] PROFILING(2336826,msprof):2026-04-13-10:59:57.637.543 [running_mode.cpp:153] >>> (tid:2336826) File size is invalid. fileName:2336826_profiling_output_record, size:-1.
	Line 3729: [WARNING] PROFILING(2336826,msprof):2026-04-13-10:59:57.637.559 [running_mode.cpp:120] >>> (tid:2336826) Get output info failed.
	Line 3730: [ERROR] PROFILING(2336826,msprof):2026-04-13-10:59:57.637.569 [utils.cpp:1661] >>> (tid:2336826) StrToUint32 failed, the input string is empty.
	Line 3731: [ERROR] PROFILING(2336826,msprof):2026-04-13-10:59:57.637.576 [running_mode.cpp:716] >>> (tid:2336826) [App Mode] Param delayTime StrToUint32 failed.
	Line 3732: [ERROR] Running profiling failed.Please check log for more info.

欢迎加入社区,感谢您对社区的贡献 🎉!

likedislike
Mrtutu
Mrtutu成员
4月13日 评论:

👋 您好,欢迎向 MindStudio msprof 提交 Issue!
我们已收到您的反馈,感谢你对开源社区的支持。🎉

📅处理时效: 维护团队将在24小时内 查看并回复您的问题(工作日)。
🔍自助查询: 在等待期间,建议您先查阅以下资料,可能已有解决方案:

📖 MindStudio msprof官方文档
📝 贡献者指南

请确保 Issue 描述清晰,包含复现步骤和日志,这将帮助我们更快定位问题。谢谢!

likedislike
ascend-robotascend-robot成员
4月13日 添加了label:usage
MrtutuMrtutu成员
4月13日 添加了label:triaged
Wwangzixuan成员
4月13日 将 Seanesmhxocism 设为负责人
wangzixuan成员
4月13日 评论:

您好,msprof报错[running_mode.cpp:153] >>> (tid:2336826) File size is invalid. fileName:2336826_profiling_output_record, size:-1.,通常是因为msprof工具没有在当前业务中感知到实际的npu进程。

请确认当前脚本中初始化的model = Qwen3VLReranker(model_name_or_path=model_name_or_path)是否有将任务下发到npu卡上,并执行相关的训推任务。如果相关任务并未下发到npu上,那么msprof是无法采集相关性能数据的。

likedislike
pyf
4月13日 评论:

@Seanesmhxocism 您好,日志中有model的输出打印, 可以确定一定有执行

likedislike
wangzixuan成员
4月13日 评论:

emm 模型可能会在cpu执行,执行了不代表一定在npu上

likedislike
pyf
4月13日 评论:

是的,这个model跑到了cpu上,给这份代码加上torch_npu的逻辑后,可以抓到timeline了

likedislike
tangmengcheng
tangmengcheng成员
4月20日 评论:

/label add resoved

likedislike
ascend-robot
ascend-robot成员
4月20日 评论:

Label Command Feedback

@tangmengcheng, Because of the repository doesn't have the label(s) resoved, it cannot be added. 🙏

likedislike
tangmengcheng
tangmengcheng成员
4月20日 评论:

/label add resolved

likedislike
ascend-robotascend-robot成员
4月20日 添加了label:resolved
Wwangzixuan成员
4月23日 issue状态由 TODO 改变为 DONE
Wwangzixuan成员
4月23日 关闭了 issue