mcTracer 日志查看以及使用教程

mcTracer

本文基于一次 mcTracer 采集得到的 tracer_out-39991.json 进行分析。目标是总结一套阅读 mcTracer JSON / mcTracer-Viewer 时间线的方法：先看事件分层，再看 host API 与 device kernel 的对应关系，最后定位 MoE 算子里真正值得优化的部分。

1. 背景：这份 JSON 是什么

这次采集得到的文件来自：

tracer_out-39991.json

JSON 是一个时间线 trace 文件，不是普通 benchmark 结果表。它记录的是应用运行期间的事件序列，例如：

host 侧 Runtime API 调用
    ↓
device 侧 kernel 执行
    ↓
device copy / memcpy / 同步 / 辅助算子

本次文件的基本情况如下：

项目	数值
JSON 大小	约 59.14 MB
总事件数	225,852
`ph=X` 完整事件数	189,069
时间跨度	约 80.98 s
flow start / finish	18,391 / 18,391
设备元数据	C500

一句话概括：

这是一份约 81 秒的 MXMACA / C500 程序运行时间线，里面既有 host 侧 Runtime API，也有 device 侧 kernel/copy 事件。

2. mcTracer JSON 的核心字段怎么读

mcTracer JSON 里最重要的是 traceEvents 数组。每个事件大致长这样：

{
  "name": "mcLaunchKernel",
  "ph": "X",
  "pid": 1,
  "tid": 123,
  "ts": 123456789,
  "dur": 5678,
  "args": {
    "co_id": 93
  }
}

阅读时先抓几个字段：

字段	含义	怎么看
`name`	事件名	API 名、kernel 名、copy 类型等
`ph`	事件类型	`X` 最重要，表示有持续时间的完整事件
`pid`	进程/泳道分类	本文件中可以粗略理解为 host、device、memcpy 三层
`tid`	线程/stream/lane	Viewer 里不同横向泳道
`ts`	timestamp	事件开始时间
`dur`	duration	事件持续时间
`args`	附加信息	grid、block、register、shared memory、bytes、co_id 等

2.1 `ph` 字段

`ph`	含义	作用
`M`	Metadata	元数据，例如设备名、线程名
`X`	Complete event	有开始时间和持续时间，是分析耗时的核心
`s`	Flow start	flow 连线起点，常用于 host API
`f`	Flow finish	flow 连线终点，常用于 device kernel/copy

最重要的是：

ph = X

因为只有 ph=X 事件才有完整的 ts + dur，可以做耗时统计。

2.2 `pid` 字段

在这份 trace 中，可以大致按下面理解：

`pid`	主要内容	例子
`pid=1`	host 侧 Runtime API	`mcLaunchKernel`、`mcMemcpyAsync`、`mcStreamSynchronize`
`pid=2`	device 侧 kernel / 部分 device event	`kernel_kernel`、`kernel_kernel_1`、PyTorch kernel、mcBLAS kernel
`pid=3`	memcpy / copy	`memcpy DTOD`、`memcpy HTOD`、`memcpy DTOH`

因此，在 Viewer 中不要把所有泳道混在一起看。一个比较实用的阅读顺序是：

先看 pid=2：device 侧真正执行了哪些 kernel
再看 pid=1：host 侧 Runtime API 是否有大量同步/等待
最后看 pid=3：copy 是否明显占用时间和带宽

2.3 `ts` / `dur` 单位

从这份文件的时间跨度和事件持续时间看，按下面换算最合理：

ms = dur / 1e6
s  = dur / 1e9

也就是说，dur 可以按纳秒级字段理解。比如：

dur = 256,313,000
≈ 256.313 ms

3. 先看总体：这次 trace 的瓶颈在哪里

我按 device 侧事件的 duration 进行了分类统计，结果非常集中：

类别	事件数	总耗时	占 device event duration 比例
TileLang custom kernels：`kernel_kernel` + `kernel_kernel_1`	444	43.19 s	91.14%
routing / reorder / scatter / gather	5,602	3.19 s	6.73%
memcpy / copy events	6,932	0.81 s	1.71%
mcBLAS / GEMM	260	0.086 s	0.18%
sort / hist / memset auxiliary	3,136	0.042 s	0.09%
elementwise / reduce / fill	1,358	0.039 s	0.08%
softmax / topk	448	0.031 s	0.06%
semaphore / sync kernel	222	0.0007 s	接近 0%

这个表非常关键。它说明本次 MoE trace 的优化重点不是泛泛地说“GPU 利用率”或者“数据搬运”，而是非常明确：

第一优化对象是 kernel_kernel；第二优化对象是 kernel_kernel_1；第三层才是 scatter/gather/reorder/device copy。

换句话说，如果当前目标是优化 MoE 算子，最应该先盯住两个 TileLang 自定义 kernel，而不是先纠结 mcBLAS、topk、softmax 这些辅助部分。

4. 最重要的两个 kernel

这份 trace 里耗时最大的两个名字是：

kernel_kernel
kernel_kernel_1

这两个名字本身语义不强，应该是 TileLang 生成出来的默认 kernel 名。结合 MoE 代码结构，它们很可能对应 fused MoE 的两个主要阶段，例如：

Step 1: gate / up projection
Step 2: down projection

但是严格对应关系需要结合源码 launch 顺序，或者后续加 MCTX 标签确认。不要只凭名字硬断言。

5. `kernel_kernel` 分析

5.1 总体统计

指标	数值
调用次数	222
总耗时	31.42 s
平均耗时	141.53 ms
中位耗时	47.29 ms
最小耗时	7.92 ms
最大耗时	256.31 ms
第一次出现	约 14.286 s
最后一次出现	约 80.213 s

这个 kernel 单独就占了 31.42 秒，是整个 trace 里最重要的优化对象。

5.2 按 launch 配置拆分

grid	block	次数	平均耗时	总耗时	资源信息
`(2056, 32, 1)`	`(128, 1, 1)`	110	253.99 ms	27.94 s	192 regs/thread，32KB dynamic shared
`(1028, 16, 1)`	`(128, 1, 1)`	110	31.00 ms	3.41 s	192 regs/thread，32KB dynamic shared
`(520, 32, 1)`	`(128, 1, 1)`	1	63.35 ms	0.063 s	192 regs/thread，32KB dynamic shared
`(260, 16, 1)`	`(128, 1, 1)`	1	7.92 ms	0.008 s	192 regs/thread，32KB dynamic shared

这里最值得注意的是大 shape：

grid = (2056, 32, 1)
block = (128, 1, 1)
调用 110 次
平均耗时约 253.99 ms
总耗时约 27.94 s

这说明本次 trace 的大部分时间都消耗在这个大 grid 的 kernel_kernel 上。

5.3 优化含义

这个 kernel 的资源信息是：

registers_per_thread = 192
dynamic_shared       = 32768 bytes
block_threads        = 128

可以从几个方向继续看：

寄存器压力：192 registers/thread 不低，可能限制 occupancy。
shared memory 使用：32KB dynamic shared memory 需要结合 C500 每 CU/SM 可用 shared memory 判断并发 block 数。
block size：当前是 128 threads/block，需要结合 wave size、TileLang 映射和 occupancy 看是否合理。
grid 形状：grid.y=32 或 16 很可能和 expert hidden dimension / block_dexpert 这类切分有关。
大 shape 与小 shape 差异：同一 kernel 在 (2056,32) 下平均 254ms，在 (1028,16) 下平均 31ms，说明不同 case 的规模差异非常明显，优化和汇报时不能混在一起平均。

6. `kernel_kernel_1` 分析

6.1 总体统计

指标	数值
调用次数	222
总耗时	11.77 s
平均耗时	53.03 ms
中位耗时	17.83 ms
最小耗时	3.18 ms
最大耗时	95.41 ms
第一次出现	约 14.349 s
最后一次出现	约 80.225 s

它是第二大耗时项。虽然比 kernel_kernel 小很多，但仍然是主要优化对象。

6.2 按 launch 配置拆分

grid	block	次数	平均耗时	总耗时	资源信息
`(2056, 56, 1)`	`(128, 1, 1)`	110	94.72 ms	10.42 s	150 regs/thread，16KB dynamic shared
`(1028, 28, 1)`	`(128, 1, 1)`	110	12.05 ms	1.33 s	150 regs/thread，16KB dynamic shared
`(520, 56, 1)`	`(128, 1, 1)`	1	23.56 ms	0.024 s	150 regs/thread，16KB dynamic shared
`(260, 28, 1)`	`(128, 1, 1)`	1	3.18 ms	0.003 s	150 regs/thread，16KB dynamic shared

大 shape 下：

grid = (2056, 56, 1)
block = (128, 1, 1)
调用 110 次
平均耗时约 94.72 ms
总耗时约 10.42 s

6.3 优化含义

这个 kernel 的资源信息是：

registers_per_thread = 150
dynamic_shared       = 16384 bytes
block_threads        = 128

和 kernel_kernel 相比，它：

寄存器更少：150 vs 192。
dynamic shared memory 更少：16KB vs 32KB。
总耗时更低：11.77s vs 31.42s。

所以优先级应该是：

先优化 kernel_kernel
再优化 kernel_kernel_1

7. 从时间线看程序阶段

把整个 81 秒 trace 按时间线拆开，大致可以分成下面几段：

相对时间	现象	判断
0–14s	Runtime API、PyTorch 辅助 kernel、少量 copy/GEMM	初始化、输入构造、辅助阶段
14.29s	出现 `(520,32)` 和 `(520,56)`	一次 warmup / functional case
20.76s	出现 `(260,16)` 和 `(260,28)`	另一次小 case / warmup
26.57–68.41s	`(2056,32)` 与 `(2056,56)` 各重复 110 次	大 shape 主性能阶段
68.41–74.52s	自定义 kernel 间隔明显	可能是 host 侧 case 切换、统计或校验
74.52–80.22s	`(1028,16)` 与 `(1028,28)` 各重复 110 次	小 shape 主性能阶段

大 shape 阶段每轮大致是：

kernel_kernel      ≈ 254 ms
kernel_kernel_1    ≈  95 ms
二者合计           ≈ 349 ms

小 shape 阶段每轮大致是：

kernel_kernel      ≈ 31 ms
kernel_kernel_1    ≈ 12 ms
二者合计           ≈ 43 ms

这个阶段划分很有用。写报告时不要只写“平均 kernel 耗时”，而应该区分：

warmup / functional case
大 shape performance case
小 shape performance case
host 侧 case 切换间隔

否则容易把不同规模的 case 混在一起，得到没有解释力的平均值。

8. Runtime API 怎么看

host 侧 Runtime API 统计如下：

Runtime API	次数	总耗时	中位耗时	最大耗时	解读
`mcMemcpyAsync`	6,932	46.54 s	2.59 us	375.58 ms	总耗时大，但中位数很小，少数调用可能阻塞/等待
`mcDeviceSynchronize`	2	414.22 ms	207.11 ms	366.88 ms	明确的 device 同步点
`mcModuleLoad`	1	251.40 ms	251.40 ms	251.40 ms	模块加载/JIT 相关一次性开销
`mcStreamSynchronize`	1,562	109.06 ms	1.89 us	82.88 ms	stream 同步
`mcLaunchKernel`	10,754	98.81 ms	4.87 us	7.82 ms	launch API 本身总量不大
`mcModuleLaunchKernel`	704	22.15 ms	6.31 us	17.42 ms	模块 kernel launch
`mcGetDevice`	140,703	27.50 ms	0.18 us	0.028 ms	次数很多但极轻，不是瓶颈

这里最容易误读的是 mcMemcpyAsync。

从 host API 侧看，它累计 46.54s，看起来非常夸张；但从 device copy 事件看，copy 真正执行的总耗时约 0.81s。因此这里不能简单说“copy 占了 46 秒”。更合理的解释是：

部分 mcMemcpyAsync host API 的 duration 包含了队列等待、依赖等待、同步或 runtime 内部条件，不等价于 device copy 的真实执行时间。

所以阅读 Runtime API 时要注意：

host API duration ≠ device kernel/copy duration

尤其是 Async API，不要直接把 host 侧 duration 当成 GPU 上实际执行的耗时。

9. memcpy / 数据搬运怎么看

device copy / memcpy 统计如下：

copy 类型	次数	总耗时	bytes 总量	最大单次 bytes
`memcpy DTOD(device,device)`	5,370	790.03 ms	426.01 GB	1.879 GB
`memcpy DTOH(device,pageable)`	448	14.74 ms	12,544 B	64 B
`memcpy DTOH(device,pinned)`	226	3.02 ms	1,794 B	8 B
`memcpy HTOD(pinned,device)`	888	2.94 ms	1.38 MB	8,224 B

几个结论：

host-device 搬运很小：HTOD 总量只有 1.38MB，DTOH 也只是很小的数据，通常是标量、检查结果或小 tensor。
主要搬运是 device-to-device：DTOD 总量 426.01GB，次数 5,370，总耗时 790ms。
DTOD 很可能来自中间数据组织：例如 clone、contiguous、token reorder、expert buffer、scatter/gather 等。
copy 不是第一瓶颈：device copy 总耗时约 0.81s，而两个 TileLang kernel 总耗时约 43.19s。

这说明这次 MoE 的主瓶颈不是 CPU 和 GPU 之间搬数据，而是 GPU 上两个自定义 kernel 的执行。

10. routing / scatter / gather 怎么看

除了两个 TileLang kernel，第三类值得关注的是 routing / reorder / scatter / gather。这类事件总耗时约 3.19s，占 device event duration 的 6.73%。

耗时较高的典型事件包括：

void at::native::_scatter_elementwise_kernel_dim2_opt<...>
void at::native::_scatter_gather_elementwise_kernel<...>
void at::native::vectorized_gather_kernel<...>

这说明 MoE 里除了 GEMM/TileLang fused kernel，本身还有一部分代价来自：

token 按 expert 分组
expert 输出写回
scatter / gather
reorder
contiguous / copy

虽然这部分不是第一瓶颈，但在优化到后期会变得重要。尤其当两个 custom kernel 优化后，routing/reorder 的占比可能会上升。

11. `co_id` 和 Viewer 里的连线怎么理解

在 mcTracer-Viewer 里，经常会看到一条线从 host 侧的 mcLaunchKernel 连到 device 侧的某个 kernel。比如：

pid=1: mcLaunchKernel, co_id=93
pid=2: void at::native::...normal_kernel..., co_id=93

这表示：

host 侧这次 mcLaunchKernel
        ↓
device 侧实际执行的这个 kernel

也就是说，同一个 co_id 是 correlation id，用来把“一次 host API”和“它对应的 device 事件”关联起来。

需要注意：

Viewer 里的连线不是函数调用栈关系，不表示 mcLaunchKernel 在 C++ 调用栈里调用了那个 device kernel 函数；它表示 host 侧 launch 和 device 侧执行之间的关联关系。

所以当你看到 mcLaunchKernel 和 void at::native::... 都是 co_id=93，这是正常的：

同一个 co_id = 同一次 launch/copy 的 host 端和 device 端

12. 在 Viewer 里应该怎么操作

打开 JSON 后，不建议一上来就缩放到某个小块里看名字。比较好的顺序是：

12.1 先看全局时间范围

先把整个 0–81s 看一遍，观察：

哪里密集？
哪里空？
哪里有长条 kernel？
哪里有明显阶段切换？

本次 trace 中，最明显的主性能阶段是：

26.57s – 68.41s：大 shape 主性能阶段
74.52s – 80.22s：小 shape 主性能阶段

12.2 再看 device 侧长条

优先看 pid=2 里的长条事件。长条一般就是大耗时 kernel。

本次最明显的是：

kernel_kernel
kernel_kernel_1

12.3 点开 kernel 看 args

点开 kernel 之后重点看：

name
duration
grid
block
registers_per_thread
dynamic_shared
co_id

例如：

kernel_kernel
grid = (2056, 32, 1)
block = (128, 1, 1)
registers_per_thread = 192
dynamic_shared = 32768

这些信息可以反推 TileLang kernel 的 launch 规模和资源压力。

12.4 再沿 flow 线回看 host API

如果想知道某个 device kernel 是哪个 host API 发起的，就沿着 flow 线回到 host 侧，看对应的：

mcLaunchKernel
mcModuleLaunchKernel
mcMemcpyAsync

核心就是看 co_id 是否一致。

12.5 最后看空档

如果两个 device kernel 中间有明显空白，说明 GPU 在那段时间可能没干活。这时要回到 host 侧看是否有：

mcStreamSynchronize
mcDeviceSynchronize
mcMemcpyAsync 阻塞
Python / PyTorch 辅助逻辑
case 切换
correctness check
日志打印

本次在 68.41s–74.52s 之间就有明显空档，更像是 case 切换、统计或校验阶段。

13. 这份 trace 能看到什么

这份 mcTracer JSON 能看到：

host 侧 MXMACA Runtime API 调用序列。
device 侧 kernel 时间线。
每个 kernel 的调用次数、持续时间、总耗时。
host API 与 device kernel/copy 的对应关系。
kernel launch config：grid、block。
部分资源信息：registers/thread、dynamic shared memory、static shared memory。
memcpy 类型、次数、bytes。
stream / device synchronize 同步点。
模块加载、kernel launch、copy、scatter/gather/reorder 等阶段。
warmup、functional case、大 shape performance case、小 shape performance case 的阶段差异。

14. 这份 trace 不能直接看到什么

它不能直接看到：

kernel 内部哪一行代码最慢。
MMA 指令是否充分利用。
HBM 带宽是否打满。
cache hit rate。
shared memory bank conflict。
wave / warp 内部 stall 原因。
ALU / tensor core / memory pipeline 的具体利用率。
每个 TileLang loop 或每个 T.gemm tile 的内部耗时。
真实 occupancy 的完整解释。
每个访存指令的 coalescing 情况。

因此，mcTracer 更像是：

时间线工具 / launch 关联工具 / 粗粒度性能定位工具

而不是完整的 kernel counter profiler。

如果要继续深入，需要结合：

mcProfiler
mx-smi --show-hbm-bandwidth
mx-smi --show-clock
mx-smi --show-clk-tr
TileLang lowered IR
MCTX 自定义标签
benchmark 内部计时

15. 对这次 MoE trace 的最终判断

这次 trace 的主要结论可以写成：

本次 MoE benchmark 的 device 侧耗时高度集中在两个 TileLang 自定义 kernel：kernel_kernel 和 kernel_kernel_1。二者合计调用 444 次，总耗时约 43.19 秒，占 device event duration 的 91.14%。其中 kernel_kernel 是第一大瓶颈，总耗时约 31.42 秒；kernel_kernel_1 是第二大瓶颈，总耗时约 11.77 秒。相比之下，routing / reorder / scatter / gather 总耗时约 3.19 秒，device copy 总耗时约 0.81 秒，mcBLAS/GEMM、softmax/topk 等辅助部分占比很低。因此，当前 MoE 优化应优先聚焦两个 TileLang 自定义 kernel 的 tile shape、thread/block 映射、寄存器使用、shared memory 使用和访存组织。

更具体地说：

第一优先级：kernel_kernel
  - 总耗时 31.42s
  - 大 shape 平均 253.99ms
  - 192 registers/thread
  - 32KB dynamic shared

第二优先级：kernel_kernel_1
  - 总耗时 11.77s
  - 大 shape 平均 94.72ms
  - 150 registers/thread
  - 16KB dynamic shared

第三优先级：routing / scatter / gather / reorder
  - 总耗时 3.19s
  - 当前不是第一瓶颈，但优化后期会变重要

第四优先级：device copy
  - 总耗时 0.81s
  - 主要是 DTOD，不是 host-device 传输

16. 后续优化建议

16.1 给 kernel 加语义标签

当前 Viewer 里只看到：

kernel_kernel
kernel_kernel_1

这不利于长期分析。建议在 MoE 的两个主要阶段加 MCTX 标签，或者让生成出来的 kernel 名带语义，例如：

MoE Step1 gate/up projection
MoE Step2 down projection
MoE routing reorder
MoE scatter output

这样下次打开 Viewer 时，不需要再靠 grid/block 猜阶段。

16.2 单独采集一个 config

当前 trace 混合了：

初始化
warmup / functional case
大 shape performance case
case 切换
小 shape performance case

如果要做严谨性能对比，建议每次只采一个 config，并固定：

batch size
seq len
top_k
expert 数量
hidden size
expert hidden size
repeat 次数
warmup 次数

否则优化前后很难公平对比。

16.3 配合 HBM 带宽日志

建议补：

timeout 120s mx-smi --show-hbm-bandwidth -i 0 -l 1000 \
  > artifacts/metrics/moe_hbm_bandwidth.log 2>&1

这样可以判断两个 custom kernel 更像是：

compute-bound
memory-bound
occupancy-bound

16.4 配合 clock / throttle 日志