Star180
190
代码
代码
Issues4
Pull Requests4
项目讨论
Wiki
分析
Star180
190
已关闭
[Bug-Report|缺陷反馈]: msserviceprofiler抓vllm性能配置"aclDataTypeConfig": "ACL_PROF_TASK_TIME"后报错acl prof create config failed. #351
kinnn8899创建于  2025年12月1日关闭于  2025年12月2日
K
kinnn8899
2025年12月1日 创建

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

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

参考vLLM 服务化性能采集工具

环境：

CANN:8.3RC1
vllm-ascend==0.11.0.rc1
msserviceprofiler==1.2.2

复现与问题描述：

  1. 添加export SERVICE_PROF_CONFIG_PATH="/data/tjl/mindie/ms_service_profiler_config.json"环境变量
  2. 启动vllm服务，stdout中无profile相关日志
  3. 执行请求发送脚本，服务侧日志有profile相关日志，并有ERROR：[ERROR] [ProfCreateConfig:541] acl prof create config failed.
  4. 请求正常返回
  5. 中断服务后才有Profiler Disabled...Profiler Disabled Successfully!相关日志。
    归档的文件目录如下，无 PROF_XXX相关日志：
/data/tjl/mindie/out_prof/1201-1122
├── ms_service_vllm-1101-244822.db
├── ms_service_vllm-1101-245059.db
├── ms_service_vllm-1101-245246.db
├── ms_service_vllm-1101-245247.db
├── ms_service_vllm-1101-245248.db
└── ms_service_vllm-1101-245249.db

正常情况下，开启"acl_task_time": 1和"aclDataTypeConfig": "ACL_PROF_TASK_TIME"后应该有PROF_XXX相关的内容。

相关脚本：

  1. ms_service_profiler_config.json
{
    "enable":0,
    "prof_dir": "/data/tjl/mindie/out_prof",
    "profiler_level": "",
    "acl_task_time": 1,
    "acl_prof_task_time_level": "L1",
    "aclDataTypeConfig": "ACL_PROF_TASK_TIME",
    "aclprofAicoreMetrics": "",
    "api_filter": "",
    "kernel_filter": "",
    "timelimit": 0,
    "domain": ""
}
  1. 请求发送脚本
PROF_CONFIG_FILE=/data/tjl/mindie/ms_service_profiler_config.json 

sed -i 's/"enable":\s*0/"enable":1/' $PROF_CONFIG_FILE # 开启 profiler

curl http://localhost:5678/v1/chat/completions \
    -H "Content-Type: application/json" \
    -d '{
    "model": "/data2/weights/Qwen_Qwen3-32B/",
    "messages": [
        {"role": "system", "content": "You are a helpful assistant."},
        {"role": "user", "content": [
            {"type": "text", "text": "你是谁?"}
        ]}
    ]
}' | jq -r '.choices[0].message.content'

sed -i 's/"enable":\s*1/"enable":0/' $PROF_CONFIG_FILE  # 关闭 profiler

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

Ascend 910B2C
CANN:8.3RC1
vllm-ascend==0.11.0.rc1
msserviceprofiler==1.2.2

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

复现与问题描述：

  1. 添加export SERVICE_PROF_CONFIG_PATH="/data/tjl/mindie/ms_service_profiler_config.json"环境变量
  2. 启动vllm服务，stdout中无profile相关日志
  3. 执行请求发送脚本，服务侧日志有profile相关日志，并有ERROR：[ERROR] [ProfCreateConfig:541] acl prof create config failed.
  4. 请求正常返回
  5. 中断服务后才有Profiler Disabled...Profiler Disabled Successfully!相关日志。

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

期望可以采集到如下profiler信息：

/data/tjl/mindie/out_prof/1201-1420
├── PROF_000001_20251201142131070_EBOORFHECOLNKDLA
│   ├── device_5
│   ├── host
│   ├── mindstudio_profiler_log
│   ├── mindstudio_profiler_output
│   └── msprof_20251201142558.db
├── PROF_000001_20251201142131076_QOKGEJGHAAELRPKC
│   ├── device_6
│   ├── host
│   ├── mindstudio_profiler_log
│   ├── mindstudio_profiler_output
│   └── msprof_20251201142558.db
├── PROF_000001_20251201142131078_OQMOALAMIILCARDC
│   ├── device_4
│   ├── host
│   ├── mindstudio_profiler_log
│   ├── mindstudio_profiler_output
│   └── msprof_20251201142558.db
├── PROF_000001_20251201142131081_CDJJKFNOEDAJGQAC
│   ├── device_7
│   ├── host
│   ├── mindstudio_profiler_log
│   ├── mindstudio_profiler_output
│   └── msprof_20251201142558.db
├── ms_service_mindie221-2-150005.db
├── ms_service_mindie221-2-150024.db
├── ms_service_mindie221-2-150029.db
├── ms_service_mindie221-2-150032.db
└── ms_service_mindie221-2-150035.db

期望解析后的输出如下(特别是PROF_XXX中的.csv文件)：

/data/tjl/mindie/out_prof/1201-1420/output
├── PROF_000001_20251201142131070_EBOORFHECOLNKDLA
│   ├── op_statistic_20251201142605.csv
│   └── op_summary_20251201142605.csv
├── PROF_000001_20251201142131076_QOKGEJGHAAELRPKC
│   ├── op_statistic_20251201142605.csv
│   └── op_summary_20251201142605.csv
├── PROF_000001_20251201142131078_OQMOALAMIILCARDC
│   ├── op_statistic_20251201142605.csv
│   └── op_summary_20251201142605.csv
├── PROF_000001_20251201142131081_CDJJKFNOEDAJGQAC
│   ├── op_statistic_20251201142605.csv
│   └── op_summary_20251201142605.csv
├── batch.csv
├── chrome_tracing.json
├── forward.csv
├── kvcache.csv
├── profiler.db
├── request.csv
└── request_status.csv

服务侧日志：

...
(APIServer pid=160629) INFO 12-01 08:46:32 [launcher.py:42] Route: /metrics, Methods: GET
(APIServer pid=160629) INFO:     Started server process [160629]
(APIServer pid=160629) INFO:     Waiting for application startup.
(APIServer pid=160629) INFO:     Application startup complete.
(APIServer pid=160629) INFO 12-01 08:48:38 [chat_utils.py:560] Detected the chat template content format to be 'string'. You can set `--chat-template-content-format` to override this.
[msservice_profiler] [PID:161054] [WARNING] [ParseLevel:470] Unknown profiler_level. Use the default profiler level.
[msservice_profiler] [PID:161054] [INFO] [ParseEnable:276] profile enable_: false
[msservice_profiler] [PID:161054] [INFO] [DynamicControl:362] Profiler Enabled...
[msservice_profiler] [PID:161054] [WARNING] [ParseLevel:470] Unknown profiler_level. Use the default profiler level.
[msservice_profiler] [PID:161054] [INFO] [ParseEnable:276] profile enable_: true
[msservice_profiler] [PID:161054] [INFO] [StartProfiler:564] prof path: /data/tjl/mindie/out_prof/1201-0846/
[msservice_profiler] [PID:161054] [ERROR] [ProfCreateConfig:541] acl prof create config failed.
[msservice_profiler] [PID:161054] [INFO] [DynamicControl:365] Profiler Enabled Successfully!
[rank0]:[W1201 08:48:38.506696594 GetCANNInfo.cpp:117] Warning: Driver Version:  is invalid or not supported yet. (function operator())
[msservice_profiler] [PID:161055] [WARNING] [ParseLevel:470] Unknown profiler_level. Use the default profiler level.
[msservice_profiler] [PID:161055] [INFO] [ParseEnable:276] profile enable_: false
[msservice_profiler] [PID:161055] [INFO] [DynamicControl:362] Profiler Enabled...
[msservice_profiler] [PID:161055] [WARNING] [ParseLevel:470] Unknown profiler_level. Use the default profiler level.
[msservice_profiler] [PID:161055] [INFO] [ParseEnable:276] profile enable_: true
[msservice_profiler] [PID:161055] [INFO] [StartProfiler:564] prof path: /data/tjl/mindie/out_prof/1201-0846/
[msservice_profiler] [PID:161055] [ERROR] [ProfCreateConfig:541] acl prof create config failed.
[msservice_profiler] [PID:161055] [INFO] [DynamicControl:365] Profiler Enabled Successfully!
[msservice_profiler] [PID:161056] [WARNING] [ParseLevel:470] Unknown profiler_level. Use the default profiler level.
[msservice_profiler] [PID:161056] [INFO] [ParseEnable:276] profile enable_: false
[msservice_profiler] [PID:161056] [INFO] [DynamicControl:362] Profiler Enabled...
[msservice_profiler] [PID:161056] [WARNING] [ParseLevel:470] Unknown profiler_level. Use the default profiler level.
[msservice_profiler] [PID:161056] [INFO] [ParseEnable:276] profile enable_: true
[msservice_profiler] [PID:161056] [INFO] [StartProfiler:564] prof path: /data/tjl/mindie/out_prof/1201-0846/
[msservice_profiler] [PID:161056] [ERROR] [ProfCreateConfig:541] acl prof create config failed.
[msservice_profiler] [PID:161056] [INFO] [DynamicControl:365] Profiler Enabled Successfully!
[rank1]:[W1201 08:48:38.507192477 GetCANNInfo.cpp:117] Warning: Driver Version:  is invalid or not supported yet. (function operator())
[rank2]:[W1201 08:48:38.507207323 GetCANNInfo.cpp:117] Warning: Driver Version:  is invalid or not supported yet. (function operator())
[msservice_profiler] [PID:161057] [WARNING] [ParseLevel:470] Unknown profiler_level. Use the default profiler level.
[msservice_profiler] [PID:161057] [INFO] [ParseEnable:276] profile enable_: false
[msservice_profiler] [PID:161057] [INFO] [DynamicControl:362] Profiler Enabled...
[msservice_profiler] [PID:161057] [WARNING] [ParseLevel:470] Unknown profiler_level. Use the default profiler level.
[msservice_profiler] [PID:161057] [INFO] [ParseEnable:276] profile enable_: true
[msservice_profiler] [PID:161057] [INFO] [StartProfiler:564] prof path: /data/tjl/mindie/out_prof/1201-0846/
[msservice_profiler] [PID:161057] [ERROR] [ProfCreateConfig:541] acl prof create config failed.
[msservice_profiler] [PID:161057] [INFO] [DynamicControl:365] Profiler Enabled Successfully!
[rank3]:[W1201 08:48:38.507542362 GetCANNInfo.cpp:117] Warning: Driver Version:  is invalid or not supported yet. (function operator())
(APIServer pid=160629) INFO 12-01 08:48:42 [loggers.py:127] Engine 000: Avg prompt throughput: 2.2 tokens/s, Avg generation throughput: 12.9 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
(APIServer pid=160629) INFO:     127.0.0.1:59426 - "POST /v1/chat/completions HTTP/1.1" 200 OK
(APIServer pid=160629) INFO 12-01 08:48:52 [loggers.py:127] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 16.0 tokens/s, Running: 0 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
(APIServer pid=160629) INFO 12-01 08:49:02 [loggers.py:127] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
(APIServer pid=160629) INFO 12-01 09:11:52 [loggers.py:127] Engine 000: Avg prompt throughput: 2.2 tokens/s, Avg generation throughput: 25.5 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.1%, Prefix cache hit rate: 0.0%
(APIServer pid=160629) INFO:     127.0.0.1:60342 - "POST /v1/chat/completions HTTP/1.1" 200 OK
(APIServer pid=160629) INFO 12-01 09:12:02 [loggers.py:127] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 2.7 tokens/s, Running: 0 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
[ERROR] TBE Subprocess[task_distribute] raise error[], main process disappeared!
[ERROR] TBE Subprocess[task_distribute] raise error[], main process disappeared!
[ERROR] TBE Subprocess[task_distribute] raise error[], main process disappeared!
[ERROR] TBE Subprocess[task_distribute] raise error[], main process disappeared!
[ERROR] TBE Subprocess[task_distribute] raise error[], main process disappeared!
[ERROR] TBE Subprocess[task_distribute] raise error[], main process disappeared!
[ERROR] TBE Subprocess[task_distribute] raise error[], main process disappeared!

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

likedislike
Kkinnn8899
2025年12月1日 修改标题为 “[Bug-Report|缺陷反馈]: msserviceprofiler抓vllm性能配置"aclDataTypeConfig": "ACL_PROF_TASK_TIME"”，原标题为“[Bug-Report|缺陷反馈]: msserviceprofiler抓vllm性能无法获得算子粒度的信息”
Kkinnn8899
2025年12月1日 修改标题为 “[Bug-Report|缺陷反馈]: msserviceprofiler抓vllm性能配置"aclDataTypeConfig": "ACL_PROF_TASK_TIME"后报错acl prof create config failed.”，原标题为“[Bug-Report|缺陷反馈]: msserviceprofiler抓vllm性能配置"aclDataTypeConfig": "ACL_PROF_TASK_TIME"”
Masaka
Masaka成员
2025年12月2日 评论：

有使用ASCEND_RT_VISIBLE_DEVICES这个环境变量指定使用的NPU吗？

likedislike
K
kinnn8899
2025年12月2日 评论：

有使用ASCEND_RT_VISIBLE_DEVICES这个环境变量指定使用的NPU吗？

@minghang_c

是的，在步骤2中启动vllm服务的脚本中通过export ASCEND_RT_VISIBLE_DEVICES=4,5,6,7设置了使用的NPU。

likedislike
C
ChenHuiwen成员
2025年12月2日 评论：

使用ASCEND_RT_VISIBLE_DEVICES指定卡为试用环境变量，采集工具未做适配，默认采集0卡。如需采集指定npu，建议在起容器的时候通过device指定。
image.png

likedislike
K
kinnn8899
2025年12月2日 评论：

使用ASCEND_RT_VISIBLE_DEVICES指定卡为试用环境变量，采集工具未做适配，默认采集0卡。如需采集指定npu，建议在起容器的时候通过device指定。
image.png

@ChenHuiwen

感谢您，使用你的方法，该问题已经成功解决。

likedislike
CChenHuiwen成员
2025年12月2日 issue状态由 TODO 改变为 DONE
CChenHuiwen成员
2025年12月2日 关闭了 issue
AAiBoGe成员
1月6日 关联了看板：msit