已关闭
[Profiler] 集群时间拆解表「周期耗时」列跨行混用 step_trace_time.csv 与 cluster_time_summary,且未提示 free 口径与 MindStudio Insight 不一致 #291
CodeLibb创建于  28 天前关闭于  14 天前
CodeLibb
28 天前 创建

本 Issue 来自昇腾「淬火行动」广州专场 MindStudio msagent 众测,被测版本 v26.1.0a2。

环境

项 值
msagent v26.1.0a2,子 Agent Profiler(默认)
LLM provider openai,base_url https://api.deepseek.com,model deepseek-v4-flash
MCP msprof-mcp Enabled
msprof-analyze 8.5.2
容器 quay.io/ascend/vllm-ascend:v0.13.0,aarch64
数据 Qwen3-32B Profiling,4 Rank,Level1,DB 类型;SHA256 cc302d549c3c7cdd671746fc9cf046a896110bf38abb8d17a2a69bc8e6e435ee
数据来源 https://gitcode.com/hummel_mao/msinsight/releases/download/202605_kernel_launch/Qwen3-32B.zip
数据完整性 解压后 466 个文件逐一 sha256 与压缩包内原文全等;分析输出均写往 -o 指定目录,输入目录 mtime 未变

现状问题

对该数据连续提问快慢卡后,第 3 轮(评估快慢卡问题造成的影响,拖慢了多少时间)输出的
「当前基线」表存在三个问题。三者都不影响定性结论(Rank1/2 为 Host 下发型慢卡,经核对正确),
但都会阻碍用户复核数值。

问题 A:同一列的四行取自两个不同数据源

agent 输出的表:

| Rank      | 周期耗时  | 计算    | 通信(未重叠) | 其中:通信等待 | Free空闲 |
| 0(受害) | 1421.9ms | 333.8ms | 447.8ms      | 441.1ms       | 625.0ms  |
| 1(慢卡) | 1422.8ms | 332.6ms | 203.8ms      | 197.0ms       | 869.5ms  |
| 2(慢卡) | 1414.6ms | 335.4ms | 247.8ms      | 241.0ms       | 823.6ms  |
| 3(受害) | 1415.3ms | 334.2ms | 445.0ms      | 438.2ms       | 628.4ms  |

逐格溯源(单位 ms):

Rank agent 周期耗时 ClusterTimeSummary.stepTime step_trace_time.csv Stage 实际取自
0 1421.9 1414.0 1421.9 CSV
1 1422.8 1413.9 1422.8 CSV
2 1414.6 1414.6 1422.5 cluster_time_summary
3 1415.3 1415.3 1421.1 cluster_time_summary

同一列前两行来自 CSV、后两行来自 cluster_time_summary。
成因可从工具调用序列看出:该轮只对 Rank0 / Rank1 执行了 read_file 读取 step_trace_time.csv
(附件截图中同屏可见工具原始返回 ...,640329.5000001277,1421920.75,... 与
...,886376.4000002164,1422767.5,...),Rank2 / Rank3 则沿用上一轮 cluster_time_summary 的结果,
两者被填进了同一列。

uc004-round3-impact.png

表头写的是「step_trace_time.csv / cluster_time_summary 显示:4 卡 Stage 全部被拉齐到 ~1414–1423ms/周期」——
同时点名两个来源,并给出一个横跨两者的区间(1414 来自 cluster_time_summary,1423 来自 CSV),
但未说明哪一行取自哪一个。

作为对照,第 1 轮的同类表格标注了单一来源
(### 关键证据 2:宏观时间拆解(cluster_time_summary)),四行数值全部取自该表,
与工具返回逐位一致。说明 Profiler 具备正确标注的能力,问题出在跨轮次复用数据时:

issue02-01-agent-table-round1.png

问题 B:表中缺少 memory 分量,行内无法自洽

ClusterTimeSummary 的时间拆解是四项而非三项,且严格自洽(实测差 0.000000):

computation + communicationNotOverlapComputation + free + memoryNotOverlapComputationCommunication == stepTime

rank0: 333767.98 + 447823.30 + 625006.10 + 7435.300 = 1414032.680 == stepTime
rank1: 332578.72 + 203812.32 + 869528.84 + 7994.380 = 1413914.260 == stepTime
rank2: 335417.58 + 247767.73 + 823581.26 + 7813.370 = 1414579.944 == stepTime
rank3: 334223.61 + 444981.87 + 628357.42 + 7786.225 = 1415349.123 == stepTime

agent 的表省略了 memory 列,于是每行的分项之和都对不上该行的周期耗时:

Rank 计算+通信+Free 该行周期耗时 差 差的构成
0 1406.6 1421.9 −15.3 memory 7.4 + 跨源差 7.9
1 1405.9 1422.8 −16.9 memory 8.0 + 跨源差 8.9
2 1406.8 1414.6 −7.8 memory 7.8
3 1407.6 1415.3 −7.7 memory 7.8

Rank2/3 只差一个 memory 分量(属省略列),Rank0/1 叠加了问题 A 的跨源差。
读者无法从表内任何信息判断这些缺口从何而来。

问题 C:free 口径与 MindStudio Insight 不一致,且未提示

任务场景要求用 MindStudio Insight 核对 agent 的分析结论,但两者的 free 定义不同:

口径 使用方 max−min Free
ClusterTimeSummary.free(不含 memory) msagent / msprof-analyze cluster -m cluster_time_summary 244,522.74 μs
ClusterStepTraceTime.free(含 memory) 数据包自带 cluster_analysis.db / MindStudio Insight 26.1.0 245,081.82 μs

MindStudio Insight 26.1.0 的 Summary 页 Advice 给出:

Free has some issues, because the max difference of "Free" has reached 245081.820000us.

insight-summary-overview.png

两者恒差一个 memoryNotOverlapComputationCommunication(逐 rank 精确相符):

rank0  ClusterStepTraceTime.free − ClusterTimeSummary.free = 7435.3000 == memoryNotOverlap 7435.3000
rank1                                                        7994.3800 ==                  7994.3800
rank2                                                        7813.3700 ==                  7813.3700
rank3                                                        7786.2250 ==                  7786.2250

agent 全程未提示自己使用的是哪一种口径。用户按任务要求拿 MindStudio Insight 核对时会发现数值对不上,
且没有任何线索判断这是工具口径差异还是分析出错。

实际后果:本 Issue 的初版正是因此把口径差误判为「agent 编造数值」而提交了错误指控,
直到查阅 ClusterTimeSummary 表结构才发现真相。一个认真复核的用户会被这个未标注的口径差直接误导。

复现步骤

  1. pip install mindstudio-agent==26.1.0a2
  2. msagent config --llm-provider openai --llm-base-url "https://api.deepseek.com" --llm-model "deepseek-v4-flash"
  3. 下载并解压上述公开数据(4 个 *_ascend_pt + cluster_analysis_output)
  4. msagent 中连续提问:
请分析 <解压目录> 中是否存在集群快慢卡问题,有什么关键证据
造成快慢卡的原因是什么
评估快慢卡问题造成的影响,拖慢了多少时间
  1. 对第 3 轮输出的表格逐格溯源:
# agent 实际读到的表(msprof-analyze 生成,-o 目录随 agent 调用而定,可从工具调用记录中看到)
python3 -c "
import sqlite3
c=sqlite3.connect('<agent -o 目录>/cluster_analysis_output/cluster_analysis.db')
cur=c.execute('select * from ClusterTimeSummary')
print([d[0] for d in cur.description])
for r in cur: print(r)
"

# 数据包自带的表(MindStudio Insight 读的就是这个)
python3 -c "
import sqlite3
c=sqlite3.connect('<解压目录>/cluster_analysis_output/cluster_analysis.db')
for r in c.execute('select \"index\",computing,communication_not_overlapped,free,stage from ClusterStepTraceTime'):
    print(r)
"

# per-rank CSV
cat <解压目录>/*_ascend_pt/ASCEND_PROFILER_OUTPUT/step_trace_time.csv

预期结果

  1. 同一列的所有行取自同一数据源;确需跨源时逐格标注;
  2. 时间拆解表列出 ClusterTimeSummary 的全部四个分项,或注明省略了 memory,
    使「分项之和 == 周期耗时」对读者成立;
  3. 输出 free 这类存在多种口径的指标时标明来源表名与口径,
    并提示其与 MindStudio Insight / 数据包自带 ClusterStepTraceTime 的差异。

实际结果

「周期耗时」列 Rank0/1 取自 CSV、Rank2/3 取自 cluster_time_summary;表中省略 memory 分量,
四行分项之和分别比该行周期耗时少 15.3 / 16.9 / 7.8 / 7.7 ms;全程未提示 free 口径,
与 MindStudio Insight 的 max difference of Free 相差 559.08 μs 而无任何说明。

优化方案(建议)

  1. 同列同源:结论表的每一列固定取自同一数据源;跨轮次复用上一次分析结果时,
    在表下注明「Rank2/3 沿用上一轮 cluster_time_summary 结果」,或补齐读取后再出表。
  2. 拆解表列全分项:对 ClusterTimeSummary 这类满足
    computation + commNotOverlap + free + memoryNotOverlap == stepTime 的表,输出时列全四项,
    或在表下写明恒等式与被省略的列。实现上可在落表前做一次断言,不通过则提示。
  3. 标注口径:每个指标标注来源表名与字段名,例如 free @ ClusterTimeSummary(不含 memory);
    对存在多口径的指标,首次输出时提示「本值与 MindStudio Insight / ClusterStepTraceTime 的 free
    相差一个 memoryNotOverlapComputationCommunication 分量」。
  4. 在 Profiler 文档中说明 cluster_time_summary 与数据包自带 ClusterStepTraceTime
    在 free / stage 上的口径差异,避免用户跨工具核对时误判。
likedislike
Mrtutu
Mrtutu成员
28 天前 评论:

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

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

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

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

likedislike
MrtutuMrtutu成员
28 天前 添加了label:triaged
yuliangbin成员
28 天前 评论:

/label add pending

likedislike
ascend-robotascend-robot成员
28 天前 添加了label:pending
CCodeLibb
28 天前 修改了issue 的描述
CCodeLibb
28 天前 修改了issue 的描述
CodeLibb
28 天前 评论:

更正:撤回本 Issue 初版中「Free 数值与数据源不匹配」的指控
提交后我做了一次逐表复核,发现初版的核心指控不成立,在此撤回并致歉。

错在哪里:初版用数据包自带 cluster_analysis_output/cluster_analysis.db 的 ClusterStepTraceTime 表作基准,而 Profiler 实际读取的是 msprof-analyze cluster -m cluster_time_summary 新生成的 ClusterTimeSummary 表。两张表的 free 定义相差一个 memory 分量。

逐 rank 核对后,Profiler 输出的数值与占比全部正确:

Rank ClusterTimeSummary.free Profiler 输出 差 表内占比 Profiler 占比
0 625006.10 μs = 625.0061 ms 625.0 ms 0.006 ms 44.20% 44.2%
1 869528.84 μs = 869.5288 ms 869.5 ms 0.029 ms 61.50% 61.5%
2 823581.26 μs = 823.5813 ms 823.6 ms 0.019 ms 58.22% 58.2%
3 628357.42 μs = 628.3574 ms 628.4 ms 0.043 ms 44.40% 44.4%
差异仅来自四舍五入到 1 位小数。初版所称的「系统性偏低 7.5~8.0ms」实为两表口径差:

ClusterStepTraceTime.free − ClusterTimeSummary.free == memoryNotOverlapComputationCommunication
rank0 7435.3000 == 7435.3000
rank1 7994.3800 == 7994.3800
rank2 7813.3700 == 7813.3700
rank3 7786.2250 == 7786.2250
ClusterTimeSummary 自身是严格自洽的(实测差 0.000000):

computation + communicationNotOverlapComputation + free + memoryNotOverlapComputationCommunication == stepTime
正文已改写,保留经复核仍然成立的三点:

  1. 第 3 轮「周期耗时」列跨行混用 step_trace_time.csv 与 cluster_time_summary(Rank0/1 来自前者,Rank2/3 来自后者);
  2. 表中省略 memory 分量,导致每行的分项之和与该行周期耗时对不上;
  3. 未提示 free 口径——ClusterTimeSummary.free 极差 244522.74 μs, 而 MindStudio Insight 26.1.0 使用的 ClusterStepTraceTime.free 极差为 245081.82 μs。
likedislike
CCodeLibb
28 天前 修改了issue 的描述
CCodeLibb
28 天前 修改了issue 的描述
CCodeLibb
28 天前 修改标题为 “[Profiler] 集群时间拆解表「周期耗时」列跨行混用 step_trace_time.csv 与 cluster_time_summary,且未提示 free 口径与 MindStudio Insight 不一致”,原标题为“Profiler 快慢卡结论表的 Free 列与两个官方数据源均不匹配,且同一张表跨行混用 step_trace_time.csv 与 cluster_analysis.db”
CCodeLibb
27 天前 关联了pull request:fix(profiler): keep cluster time evidence source-consistent
CodeLibb
27 天前 评论:

/assign @CodeLibb

likedislike
ascend-robotascend-robot成员
27 天前 将 CodeLibb 设为负责人
CCodeLibb
27 天前 修改了issue 的描述
Lleo920320成员
19 天前 关联了pull request:增加性能拆解Skills
xfeng
xfeng成员
14 天前 评论:

step_trace_time.csv / cluster_time_summary 里面关于free时间的不一致是真实存在的,cluster_time_summary里面的free是去掉了memcpy的时间,这个是后做的
1.这个更多取决于模型自己的能力,不会固定复现
2.导致每行的分项之和与该行周期耗时对不上;这个agent只是打印了关键指标,省略了一些列,要看具体的可以查看原表
3.未提示 free 口径——ClusterTimeSummary.free 极差 244522.74 μs, 而 MindStudio Insight 26.1.0 使用的 ClusterStepTraceTime.free 极差为 245081.82 μs。无需纠结这个

likedislike
xfeng
xfeng成员
14 天前 评论:

/label add resolved

likedislike
ascend-robotascend-robot成员
14 天前 添加了label:resolved
Yyuliangbin成员
14 天前 issue状态由 TODO 改变为 DONE
Yyuliangbin成员
14 天前 关闭了 issue