MXNet Profiler 使用指南从入门到源码级剖析【免费下载链接】mxnetLightweight, Portable, Flexible Distributed/Mobile Deep Learning with Dynamic, Mutation-aware Dataflow Dep Scheduler; for Python, R, Julia, Scala, Go, Javascript and more项目地址: https://gitcode.com/gh_mirrors/mxne/mxnetMXNet 采用异步执行引擎用 Python 的time模块直接测量算子耗时往往得到误导性结果。本指南以官方 Profiler 教程为主体完整讲解如何通过mxnet.profiler测量模型各算子的运行时间与内存消耗、如何将结果导出为 Chrome Tracing 可视化、如何配合 oneDNN 内部工具与 NVIDIA 底层工具联合剖析并结合本仓库源码深入解释 Profiler 的底层工作机制。读完本文你将掌握正确使用profiler.set_config/set_state/dump/dumps等 API 的姿势、环境变量自动启动与 bulk 模式开关的细节、以及面对自定义算子与符号式模型时的剖析要点。为什么不能用time模块直接测时教程首先用一个反例揭示了 MXNet 异步执行模型的核心陷阱。下面这段代码试图用 Python 的time模块分别测量矩阵乘法与asnumpy转换的耗时from time import time from mxnet import autograd, np import mxnet as mx start time() x np.random.uniform(size(2000, 2000)) y np.dot(x, x) print(Time for matrix multiplication: %f sec\n % (time() - start)) start time() y_np y.asnumpy() print(Time for converting to numpy: %f sec % (time() - start))在某次运行中矩阵乘法显示仅耗时0.005051 秒而asnumpy转换却耗时0.167693 秒——一个 2000×2000 的矩阵乘法怎么可能比一次内存拷贝还慢 30 倍答案在于在 MXNet 中所有算子都以异步方式执行。np.dot(x, x)返回时矩阵乘法并没有完成只是被排队等待执行而asnumpy是“阻塞型”操作它必须等待结果真正计算完成、并拷贝到 CPU 上的 NumPy 数组后才会返回因此它的计时里包含了此前所有排队算子的实际执行时间类似的阻塞型操作还包括 asscalar 与 wait_to_read。虽然也可以在用 NDArray.waitall() 前后手动计时但这种方法无法规模化地测量多组算子的耗时尤其是在 Sequential 或 Hybridize 之后的网络中。一句话总结在 MXNet 这类异步框架中正确测量算子耗时的唯一可靠方式是使用框架自带的 Profiler而不是外层计时器。Profiler 的正确打开方式配置 Profiler导入并配置 Profiler 非常简单全程无需修改 C 代码from mxnet import profiler profiler.set_config(profile_allTrue, aggregate_statsTrue, continuous_dumpTrue, filenameprofile_output.json)set_config的核心参数对应 python/mxnet/profiler.py 中的 docstring说明如下参数类型说明profile_allboolean开启所有类型的剖析profile_symbolicboolean是否剖析符号式Symbolic算子profile_imperativeboolean是否剖析命令式Imperative算子profile_memoryboolean是否剖析内存使用profile_apiboolean是否剖析 C APIfilenamestring剖析数据输出文件continuous_dumpboolean是否周期性把剖析数据写入文件dump_periodfloat两次数据落盘之间的间隔秒aggregate_statsboolean是否在内存中维护聚合统计供profiler.dumps()打印到控制台注意该选项有少量性能开销gpu_memory_profile_filename_prefixstringGPU 内存剖析文件的文件名前缀profile_processstring剖析 kvstore 的server还是worker仅在dist类型 kvstore 下可剖析 server默认worker从源码看set_config最终通过MXSetProcessProfilerConfig把配置下发给 C 层在 src/profiler/profiler.cc 中C 端Profiler::SetConfig会设置模式位掩码、输出文件名并unlink旧文件、按需创建聚合统计对象AggregateStats。而在 src/profiler/profiler.h 中可以看到剖析模式是一个位掩码枚举kSymbolic 1、kImperative 2、kAPI 4、kMemory 8默认模式为kSymbolic | kAPI | kMemory。构建一个用于演示的小型 CNN教程使用一个两层卷积的小网络配合 MNIST 数据来演示剖析流程from mxnet import gluon net gluon.nn.HybridSequential() net.add(gluon.nn.Conv2D(channels20, kernel_size5, activationrelu)) net.add(gluon.nn.MaxPool2D(pool_size2, strides2)) net.add(gluon.nn.Conv2D(channels50, kernel_size5, activationrelu)) net.add(gluon.nn.MaxPool2D(pool_size2, strides2)) net.add(gluon.nn.Flatten()) net.add(gluon.nn.Dense(512, activationrelu)) net.add(gluon.nn.Dense(10))准备 MNIST 数据与训练迭代函数from mxnet.gluon.data.vision import transforms dataset gluon.data.vision.MNIST(trainTrue) dataset dataset.transform_first(transforms.ToTensor()) dataloader gluon.data.DataLoader(dataset, batch_size64, shuffleTrue) # Use GPU if available if mx.device.num_gpus(): device mx.gpu() else: device mx.cpu() net.initialize(mx.init.Xavier(), devicedevice) trainer gluon.Trainer(net.collect_params(), sgd, {learning_rate: 0.1}) softmax_cross_entropy gluon.loss.SoftmaxCrossEntropyLoss() def run_training_iteration(data, label): data data.to_device(device) label label.to_device(device) with autograd.record(): output net(data) loss softmax_cross_entropy(output, label) loss.backward() trainer.step(data.shape[0])用 set_state 控制剖析起止网络第一次前向时MXNet 需要做大量“暖机”工作推断各参数形状、为中间结果与最终输出分配内存等因此第一轮迭代的剖析结果不具备代表性应当跳过itr iter(dataloader) run_training_iteration(*next(itr)) # 不剖析第一轮随后开启剖析data, label next(itr) # 让 profiler 开始记录 profiler.set_state(run) run_training_iteration(*next(itr)) # 确保所有异步操作都已完成 mx.npx.waitall() # 停止记录 profiler.set_state(stop) # 把结果落盘到日志文件 profiler.dump()set_state接受run/stop两个状态对应 C 端的ProfilerState枚举见 src/profiler/profiler.h。此外你还可以在运行过程中用profiler.pause()/profiler.resume()只剖析感兴趣的那段代码两者最终都调用MXProcessProfilePause见 python/mxnet/profiler.py。仓库中的示例脚本 example/profiler/profiler_matmul.py 展示了同样的模式它循环执行 100 次 GPU 上的 4096×4096 矩阵乘法在第 50 次迭代set_state(run)、第 70 次迭代set_state(stop)从而只剖析中间 20 次迭代。而 example/profiler/profiler_ndarray.py 则用profile_allTrue剖析一串 NDArray 算子测试。更多示例说明见 example/profiler/README.md。用环境变量自动启动 Profiler如果不想改代码可以通过环境变量自动启动剖析覆盖整个脚本的执行过程$ MXNET_PROFILER_AUTOSTART1 python my_script.py当MXNET_PROFILER_AUTOSTART被设为1时MXNet 会自动启动 Profiler输出文件为当前目录下的profile.json。底层实现在 src/profiler/profiler.ccProfiler 构造函数读取该环境变量若为真则把状态置为kRunning并启用输出同时调用vtune_resume()避免干扰纯 VTune 分析。注意剖析输出可能非常庞大因此教程建议优先使用上一节的set_stateAPI 只剖析关键代码段而不是全程自动剖析。提升剖析粒度关闭 bulk 执行模式MXNet 会以“批量模式”bulk mode执行计算图以减少符号算子之间的内核启动间隙从而加快执行。但这会降低剖析输出的粒度——多个算子可能被合并显示。如果希望得到每个算子独立的剖析结果请设置$ MXNET_EXEC_BULK_EXEC_INFERENCE0 MXNET_EXEC_BULK_EXEC_TRAIN0 python my_script.py在源码中这两个开关对应 include/mxnet/imperative.h 里的dmlc::GetEnv读取MXNET_EXEC_BULK_EXEC_INFERENCE与MXNET_EXEC_BULK_EXEC_TRAIN默认均为true即默认开启 bulk另外还有MXNET_EXEC_BULK_EXEC_MAX_NODE_TRAIN_FWD/_BWD控制单次批量合并的最大节点数默认继承自MXNET_EXEC_BULK_EXEC_MAX_NODE_TRAIN默认 15。这些环境变量的汇总说明也可以在本仓库的 docs/static_site/src/pages/api/faq/env_var.md 中找到其中明确指出如需每个算子的剖析结果应将MXNET_EXEC_BULK_EXEC_INFERENCE、MXNET_EXEC_BULK_EXEC_MAX_NODE_TRAIN与MXNET_EXEC_BULK_EXEC_TRAIN都设为 0。此外对 Gluon 构建的网络而言未 Hybridize 的网络会得到更细粒度的剖析输出Hybridize 后算子可能被融合fused剖析结果中会出现融合算子给调试带来困扰。查看 Profiler 输出1. 控制台查看聚合统计profiler.dumps()可以把内存中的聚合统计打印到控制台内容包括每个算子的耗时、每个 C API 的耗时、以及 CPU 与 GPU 上的内存消耗profiler.set_state(run) profiler.set_state(stop) print(profiler.dumps())dumps()还支持若干进阶参数见 python/mxnet/profiler.pyreset控制是否清空此前累积的统计format可选table或jsonsort_by可选total、avg、min、max、count之一默认按total排序ascending控制升序/降序。在 C 端聚合统计由AggregateStats类维护见 src/profiler/aggregate_stats.hDurationStat::SaveAggregatesrc/profiler/profiler.h会把每条记录的耗时累加进total_aggregate_并更新max_aggregate_/min_aggregate_与total_count_这正是dumps()输出中各统计字段的数据来源。2. 浏览器中查看 Chrome Tracingprofiler.dump()会把剖析数据写成 JSON 文件可用 Chrome 浏览器打开chrome://tracing加载查看profiler.dump(finishedFalse)生成的 JSON 采用 Chrome Trace Event 格式。在 src/profiler/profiler.cc 的DumpProfile中可以看到输出结构先是traceEvents数组随后按设备每个 CPU 核心、GPU、CPU pinned、CPU shared 各对应一个 pid输出事件最后以displayTimeUnit: ms收尾事件类型定义在 src/profiler/profiler.h 的EventType枚举中包含kDurationBegin(B)、kDurationEnd(E)、kComplete(X)、kCounter(C)、kAsyncNestableStart(b)、kFlowStart(s)等与 Chrome Tracing 规范一一对应注意finished参数设为False可防止 Profiler 在本次 dump 后结束。如果直接调用profiler.dump()默认finishedTrue此后将无法再剖析模型剩余部分。缩放时间轴即可看到每个算子的执行顺序与耗时。剖析 oneDNN 算子对于 oneDNN原 MKL-DNN算子库本身提供了内部剖析工具。首先设置DNNL_VERBOSE1开启内部剖析$ DNNL_VERBOSE1 python my_script.py dnnl_verbose.log日志中会为每个 oneDNN 原语primitive记录创建与执行细节例如dnnl_verbose,info,DNNL v1.1.2 (commit cb2cc7ac17ff4e2ef50805c7048d33256d82be4d) dnnl_verbose,info,Detected ISA is Intel AVX-512 with Intel DL Boost dnnl_verbose,exec,cpu,convolution,jit:avx512_common,forward_inference,src_f32::blocked:aBcd16b:f0 wei_f32::blocked:ABcd16b16a:f0 bia_undef::undef::f0 dst_f32::blocked:aBcd16b:f0,,alg:convolution_direct,mb32_ic32oc32_ih256oh256kh3sh1dh0ph1_iw256ow256kw3sw1dw0pw1,20.7539每行日志以逗号分隔第 11 个字段索引从 1 起是耗时。例如要统计所有convolution原语的总执行时间$ cat dnnl_verbose.log | grep exec,cpu,convolution | awk BEGIN{FS,} {SUM$11} END {print SUM}若设置DNNL_VERBOSE2则同时收集每个原语的创建时间与执行时间可分别用grep create,cpu,convolution与grep exec,cpu,convolution统计$ cat dnnl_verbose.log | grep create,cpu,convolution | awk BEGIN{FS,} {SUM$11} END {print SUM} $ cat dnnl_verbose.log | grep exec,cpu,convolution | awk BEGIN{FS,} {SUM$11} END {print SUM}本仓库默认启用 oneDNN 构建详见 DNNL_README.md上述方法适用于 CPU 上的卷积、池化等 oneDNN 算子。剖析自定义算子Custom Operators当内置 NDArray 算子无法满足模型需求时可以在 Python 中定义自定义算子。在自定义算子的forward()与backward()中通常包含两类代码“纯 Python”代码含 NumPy 算子“子算子”在forward()/backward()中调用的 NDArray 算子。MXNet Profiler无需额外配置即可同时剖析这两类代码一次自定义算子调用会被拆分为一个纯 Python 事件和若干子算子事件且所有事件名都会带上所调用自定义算子的名字作为前缀。以一个简单的MyAddOne算子为例class MyAddOne(mx.operator.CustomOp): def forward(self, is_train, req, in_data, out_data, aux): self.assign(out_data[0], req[0], in_data[0]1) def backward(self, req, out_grad, in_data, out_data, in_grad, aux): self.assign(in_grad[0], req[0], out_grad[0]) mx.operator.register(MyAddOne) class CustomAddOneProp(mx.operator.CustomOpProp): def __init__(self): super(CustomAddOneProp, self).__init__(need_top_gradTrue) def list_arguments(self): return [data] def list_outputs(self): return [output] def infer_shape(self, in_shape): return [in_shape[0]], [in_shape[0]], [] def create_operator(self, device, shapes, dtypes): return MyAddOne() inp mx.np.zeros(shape(500, 500)) profiler.set_config(profile_allTrue, continuous_dumpTrue, \ aggregate_statsTrue) profiler.set_state(run) w nd.Custom(inp, op_typeMyAddOne) mx.npx.waitall() profiler.set_state(stop) print(profiler.dumps()) profiler.dump(finishedFalse)在 Chrome Tracing 中所有自定义算子相关事件都落在Custom Operator域下可以清楚看到MyAddOne::pure_python先执行随后是其子算子如CopyCPU2CPU、_plus_scalr的执行顺序。关键注意点即使在符号式Symbolic模式下使用自定义算子也必须开启profile_imperativeTrue才能看到上述信息——因为自定义算子内部的纯 Python 代码与子算子依然是按命令式调用的。符号式等价代码如下# 方式一profile_all 全开 profiler.set_config(profile_allTrue, aggregate_statsTrue, continuous_dumpTrue) # 方式二显式同时开启 symbolic 与 imperative profiler.set_config(profile_symbolicTrue, profile_imperativeTrue, \ aggregate_statsTrue, continuous_dumpTrue) profiler.set_state(run) # 符号式模式 a mx.symbol.Variable(a) b mx.symbol.Custom(dataa, op_typeMyAddOne) c b.bind(mx.cpu(), {a: inp}) y c.forward() mx.npx.waitall() profiler.set_state(stop) print(profiler.dumps()) profiler.dump()需要注意的几条规则dump()与finished只要不打算结束 dump就应使用profiler.dump(finishedFalse)否则在模型运行中途调用profiler.dump()可能引发意外行为且之后若再调用profiler.set_config()会导致程序报错。只能 dump 到一个文件不要在模型运行中途用profiler.set_config(filenamenew_name.json)更换目标文件否则会产生不完整的 dump 输出。进阶配合 NVIDIA 剖析工具MXNet Profiler 是剖析 MXNet 代码的推荐起点但 NVIDIA 还提供了低层 CUDA 剖析工具NVProf、Visual ProfilerCUDA 9 / CUDA 10 工具包自带与Nsight ComputeCUDA 10 工具包自带可用于剖析运行在 CUDA 9 上的代码。它们可以剖析任意可执行程序因此也适用于运行 MXNet 的 Python 脚本并能与 MXNet Profiler 联合使用上层看 MXNet 的算子级信息下层看 CUDA kernel 级信息。NVProf 与 Visual Profiler从命令行用nvprof包裹 Python 脚本执行$ nvprof -o my_profile.nvvp python my_profiler_script.py输出类似11588 NVPROF is profiling process 11588, command: python my_profiler_script.py 11588 Generated result file: /home/user/Development/mxnet/ci/my_profile.nvvp生成的.nvvp文件会用 NVTX range对应 MXNet 算子标注与 NVProf 标准时间线一同展示便于建立“MXNet 算子 → CUDA kernel 调用”的映射关系。文件可用 Visual Profiler 打开时间线上方是 CPU 侧任务驱动操作、内存拷贝、MXNet 引擎算子调用、命令式 API 调用下方是同一时间段内 GPU 上活跃的 kernel。放大某个反向卷积算子可以看到它由多个 GPU kernel 组成如 cuDNN Winograd 卷积调用、FFT 调用点选任一 kernel 还能看到占用率与理论值的对比、共享内存使用量、执行时长等 GPU 性能指标。Nsight ComputeNsight Compute 不提供时间线视图但提供每个 kernel 的大量底层统计并支持多次运行对比例如建立 baseline。提示如果nvprof不在 PATH 中可以在 CUDA 安装目录下找到它。更多设置细节可参考 MXNet 官方讨论区。结语对异步执行的深度学习框架而言性能剖析必须依赖框架自身的 Profiler 而非外部计时器。通过mxnet.profiler的配置、状态控制、聚合统计与 Chrome Tracing 导出配合 bulk 模式开关与 oneDNN / NVIDIA 工具你可以精确定位训练与推理中的热点算子为后续优化指明方向。仓库中的 example/profiler 提供了矩阵乘法、NDArray 算子等可直接运行的剖析示例配合 tests/python/unittest/test_profiler.py 可以快速验证你对 Profiler API 的理解。【免费下载链接】mxnetLightweight, Portable, Flexible Distributed/Mobile Deep Learning with Dynamic, Mutation-aware Dataflow Dep Scheduler; for Python, R, Julia, Scala, Go, Javascript and more项目地址: https://gitcode.com/gh_mirrors/mxne/mxnet创作声明：本文部分内容由AI辅助生成（AIGC），仅供参考 MXNet Profiler 使用指南：从入门到源码级剖析
MXNet Profiler 使用指南从入门到源码级剖析【免费下载链接】mxnetLightweight, Portable, Flexible Distributed/Mobile Deep Learning with Dynamic, Mutation-aware Dataflow Dep Scheduler; for Python, R, Julia, Scala, Go, Javascript and more项目地址: https://gitcode.com/gh_mirrors/mxne/mxnetMXNet 采用异步执行引擎用 Python 的time模块直接测量算子耗时往往得到误导性结果。本指南以官方 Profiler 教程为主体完整讲解如何通过mxnet.profiler测量模型各算子的运行时间与内存消耗、如何将结果导出为 Chrome Tracing 可视化、如何配合 oneDNN 内部工具与 NVIDIA 底层工具联合剖析并结合本仓库源码深入解释 Profiler 的底层工作机制。读完本文你将掌握正确使用profiler.set_config/set_state/dump/dumps等 API 的姿势、环境变量自动启动与 bulk 模式开关的细节、以及面对自定义算子与符号式模型时的剖析要点。为什么不能用time模块直接测时教程首先用一个反例揭示了 MXNet 异步执行模型的核心陷阱。下面这段代码试图用 Python 的time模块分别测量矩阵乘法与asnumpy转换的耗时from time import time from mxnet import autograd, np import mxnet as mx start time() x np.random.uniform(size(2000, 2000)) y np.dot(x, x) print(Time for matrix multiplication: %f sec\n % (time() - start)) start time() y_np y.asnumpy() print(Time for converting to numpy: %f sec % (time() - start))在某次运行中矩阵乘法显示仅耗时0.005051 秒而asnumpy转换却耗时0.167693 秒——一个 2000×2000 的矩阵乘法怎么可能比一次内存拷贝还慢 30 倍答案在于在 MXNet 中所有算子都以异步方式执行。np.dot(x, x)返回时矩阵乘法并没有完成只是被排队等待执行而asnumpy是“阻塞型”操作它必须等待结果真正计算完成、并拷贝到 CPU 上的 NumPy 数组后才会返回因此它的计时里包含了此前所有排队算子的实际执行时间类似的阻塞型操作还包括 asscalar 与 wait_to_read。虽然也可以在用 NDArray.waitall() 前后手动计时但这种方法无法规模化地测量多组算子的耗时尤其是在 Sequential 或 Hybridize 之后的网络中。一句话总结在 MXNet 这类异步框架中正确测量算子耗时的唯一可靠方式是使用框架自带的 Profiler而不是外层计时器。Profiler 的正确打开方式配置 Profiler导入并配置 Profiler 非常简单全程无需修改 C 代码from mxnet import profiler profiler.set_config(profile_allTrue, aggregate_statsTrue, continuous_dumpTrue, filenameprofile_output.json)set_config的核心参数对应 python/mxnet/profiler.py 中的 docstring说明如下参数类型说明profile_allboolean开启所有类型的剖析profile_symbolicboolean是否剖析符号式Symbolic算子profile_imperativeboolean是否剖析命令式Imperative算子profile_memoryboolean是否剖析内存使用profile_apiboolean是否剖析 C APIfilenamestring剖析数据输出文件continuous_dumpboolean是否周期性把剖析数据写入文件dump_periodfloat两次数据落盘之间的间隔秒aggregate_statsboolean是否在内存中维护聚合统计供profiler.dumps()打印到控制台注意该选项有少量性能开销gpu_memory_profile_filename_prefixstringGPU 内存剖析文件的文件名前缀profile_processstring剖析 kvstore 的server还是worker仅在dist类型 kvstore 下可剖析 server默认worker从源码看set_config最终通过MXSetProcessProfilerConfig把配置下发给 C 层在 src/profiler/profiler.cc 中C 端Profiler::SetConfig会设置模式位掩码、输出文件名并unlink旧文件、按需创建聚合统计对象AggregateStats。而在 src/profiler/profiler.h 中可以看到剖析模式是一个位掩码枚举kSymbolic 1、kImperative 2、kAPI 4、kMemory 8默认模式为kSymbolic | kAPI | kMemory。构建一个用于演示的小型 CNN教程使用一个两层卷积的小网络配合 MNIST 数据来演示剖析流程from mxnet import gluon net gluon.nn.HybridSequential() net.add(gluon.nn.Conv2D(channels20, kernel_size5, activationrelu)) net.add(gluon.nn.MaxPool2D(pool_size2, strides2)) net.add(gluon.nn.Conv2D(channels50, kernel_size5, activationrelu)) net.add(gluon.nn.MaxPool2D(pool_size2, strides2)) net.add(gluon.nn.Flatten()) net.add(gluon.nn.Dense(512, activationrelu)) net.add(gluon.nn.Dense(10))准备 MNIST 数据与训练迭代函数from mxnet.gluon.data.vision import transforms dataset gluon.data.vision.MNIST(trainTrue) dataset dataset.transform_first(transforms.ToTensor()) dataloader gluon.data.DataLoader(dataset, batch_size64, shuffleTrue) # Use GPU if available if mx.device.num_gpus(): device mx.gpu() else: device mx.cpu() net.initialize(mx.init.Xavier(), devicedevice) trainer gluon.Trainer(net.collect_params(), sgd, {learning_rate: 0.1}) softmax_cross_entropy gluon.loss.SoftmaxCrossEntropyLoss() def run_training_iteration(data, label): data data.to_device(device) label label.to_device(device) with autograd.record(): output net(data) loss softmax_cross_entropy(output, label) loss.backward() trainer.step(data.shape[0])用 set_state 控制剖析起止网络第一次前向时MXNet 需要做大量“暖机”工作推断各参数形状、为中间结果与最终输出分配内存等因此第一轮迭代的剖析结果不具备代表性应当跳过itr iter(dataloader) run_training_iteration(*next(itr)) # 不剖析第一轮随后开启剖析data, label next(itr) # 让 profiler 开始记录 profiler.set_state(run) run_training_iteration(*next(itr)) # 确保所有异步操作都已完成 mx.npx.waitall() # 停止记录 profiler.set_state(stop) # 把结果落盘到日志文件 profiler.dump()set_state接受run/stop两个状态对应 C 端的ProfilerState枚举见 src/profiler/profiler.h。此外你还可以在运行过程中用profiler.pause()/profiler.resume()只剖析感兴趣的那段代码两者最终都调用MXProcessProfilePause见 python/mxnet/profiler.py。仓库中的示例脚本 example/profiler/profiler_matmul.py 展示了同样的模式它循环执行 100 次 GPU 上的 4096×4096 矩阵乘法在第 50 次迭代set_state(run)、第 70 次迭代set_state(stop)从而只剖析中间 20 次迭代。而 example/profiler/profiler_ndarray.py 则用profile_allTrue剖析一串 NDArray 算子测试。更多示例说明见 example/profiler/README.md。用环境变量自动启动 Profiler如果不想改代码可以通过环境变量自动启动剖析覆盖整个脚本的执行过程$ MXNET_PROFILER_AUTOSTART1 python my_script.py当MXNET_PROFILER_AUTOSTART被设为1时MXNet 会自动启动 Profiler输出文件为当前目录下的profile.json。底层实现在 src/profiler/profiler.ccProfiler 构造函数读取该环境变量若为真则把状态置为kRunning并启用输出同时调用vtune_resume()避免干扰纯 VTune 分析。注意剖析输出可能非常庞大因此教程建议优先使用上一节的set_stateAPI 只剖析关键代码段而不是全程自动剖析。提升剖析粒度关闭 bulk 执行模式MXNet 会以“批量模式”bulk mode执行计算图以减少符号算子之间的内核启动间隙从而加快执行。但这会降低剖析输出的粒度——多个算子可能被合并显示。如果希望得到每个算子独立的剖析结果请设置$ MXNET_EXEC_BULK_EXEC_INFERENCE0 MXNET_EXEC_BULK_EXEC_TRAIN0 python my_script.py在源码中这两个开关对应 include/mxnet/imperative.h 里的dmlc::GetEnv读取MXNET_EXEC_BULK_EXEC_INFERENCE与MXNET_EXEC_BULK_EXEC_TRAIN默认均为true即默认开启 bulk另外还有MXNET_EXEC_BULK_EXEC_MAX_NODE_TRAIN_FWD/_BWD控制单次批量合并的最大节点数默认继承自MXNET_EXEC_BULK_EXEC_MAX_NODE_TRAIN默认 15。这些环境变量的汇总说明也可以在本仓库的 docs/static_site/src/pages/api/faq/env_var.md 中找到其中明确指出如需每个算子的剖析结果应将MXNET_EXEC_BULK_EXEC_INFERENCE、MXNET_EXEC_BULK_EXEC_MAX_NODE_TRAIN与MXNET_EXEC_BULK_EXEC_TRAIN都设为 0。此外对 Gluon 构建的网络而言未 Hybridize 的网络会得到更细粒度的剖析输出Hybridize 后算子可能被融合fused剖析结果中会出现融合算子给调试带来困扰。查看 Profiler 输出1. 控制台查看聚合统计profiler.dumps()可以把内存中的聚合统计打印到控制台内容包括每个算子的耗时、每个 C API 的耗时、以及 CPU 与 GPU 上的内存消耗profiler.set_state(run) profiler.set_state(stop) print(profiler.dumps())dumps()还支持若干进阶参数见 python/mxnet/profiler.pyreset控制是否清空此前累积的统计format可选table或jsonsort_by可选total、avg、min、max、count之一默认按total排序ascending控制升序/降序。在 C 端聚合统计由AggregateStats类维护见 src/profiler/aggregate_stats.hDurationStat::SaveAggregatesrc/profiler/profiler.h会把每条记录的耗时累加进total_aggregate_并更新max_aggregate_/min_aggregate_与total_count_这正是dumps()输出中各统计字段的数据来源。2. 浏览器中查看 Chrome Tracingprofiler.dump()会把剖析数据写成 JSON 文件可用 Chrome 浏览器打开chrome://tracing加载查看profiler.dump(finishedFalse)生成的 JSON 采用 Chrome Trace Event 格式。在 src/profiler/profiler.cc 的DumpProfile中可以看到输出结构先是traceEvents数组随后按设备每个 CPU 核心、GPU、CPU pinned、CPU shared 各对应一个 pid输出事件最后以displayTimeUnit: ms收尾事件类型定义在 src/profiler/profiler.h 的EventType枚举中包含kDurationBegin(B)、kDurationEnd(E)、kComplete(X)、kCounter(C)、kAsyncNestableStart(b)、kFlowStart(s)等与 Chrome Tracing 规范一一对应注意finished参数设为False可防止 Profiler 在本次 dump 后结束。如果直接调用profiler.dump()默认finishedTrue此后将无法再剖析模型剩余部分。缩放时间轴即可看到每个算子的执行顺序与耗时。剖析 oneDNN 算子对于 oneDNN原 MKL-DNN算子库本身提供了内部剖析工具。首先设置DNNL_VERBOSE1开启内部剖析$ DNNL_VERBOSE1 python my_script.py dnnl_verbose.log日志中会为每个 oneDNN 原语primitive记录创建与执行细节例如dnnl_verbose,info,DNNL v1.1.2 (commit cb2cc7ac17ff4e2ef50805c7048d33256d82be4d) dnnl_verbose,info,Detected ISA is Intel AVX-512 with Intel DL Boost dnnl_verbose,exec,cpu,convolution,jit:avx512_common,forward_inference,src_f32::blocked:aBcd16b:f0 wei_f32::blocked:ABcd16b16a:f0 bia_undef::undef::f0 dst_f32::blocked:aBcd16b:f0,,alg:convolution_direct,mb32_ic32oc32_ih256oh256kh3sh1dh0ph1_iw256ow256kw3sw1dw0pw1,20.7539每行日志以逗号分隔第 11 个字段索引从 1 起是耗时。例如要统计所有convolution原语的总执行时间$ cat dnnl_verbose.log | grep exec,cpu,convolution | awk BEGIN{FS,} {SUM$11} END {print SUM}若设置DNNL_VERBOSE2则同时收集每个原语的创建时间与执行时间可分别用grep create,cpu,convolution与grep exec,cpu,convolution统计$ cat dnnl_verbose.log | grep create,cpu,convolution | awk BEGIN{FS,} {SUM$11} END {print SUM} $ cat dnnl_verbose.log | grep exec,cpu,convolution | awk BEGIN{FS,} {SUM$11} END {print SUM}本仓库默认启用 oneDNN 构建详见 DNNL_README.md上述方法适用于 CPU 上的卷积、池化等 oneDNN 算子。剖析自定义算子Custom Operators当内置 NDArray 算子无法满足模型需求时可以在 Python 中定义自定义算子。在自定义算子的forward()与backward()中通常包含两类代码“纯 Python”代码含 NumPy 算子“子算子”在forward()/backward()中调用的 NDArray 算子。MXNet Profiler无需额外配置即可同时剖析这两类代码一次自定义算子调用会被拆分为一个纯 Python 事件和若干子算子事件且所有事件名都会带上所调用自定义算子的名字作为前缀。以一个简单的MyAddOne算子为例class MyAddOne(mx.operator.CustomOp): def forward(self, is_train, req, in_data, out_data, aux): self.assign(out_data[0], req[0], in_data[0]1) def backward(self, req, out_grad, in_data, out_data, in_grad, aux): self.assign(in_grad[0], req[0], out_grad[0]) mx.operator.register(MyAddOne) class CustomAddOneProp(mx.operator.CustomOpProp): def __init__(self): super(CustomAddOneProp, self).__init__(need_top_gradTrue) def list_arguments(self): return [data] def list_outputs(self): return [output] def infer_shape(self, in_shape): return [in_shape[0]], [in_shape[0]], [] def create_operator(self, device, shapes, dtypes): return MyAddOne() inp mx.np.zeros(shape(500, 500)) profiler.set_config(profile_allTrue, continuous_dumpTrue, \ aggregate_statsTrue) profiler.set_state(run) w nd.Custom(inp, op_typeMyAddOne) mx.npx.waitall() profiler.set_state(stop) print(profiler.dumps()) profiler.dump(finishedFalse)在 Chrome Tracing 中所有自定义算子相关事件都落在Custom Operator域下可以清楚看到MyAddOne::pure_python先执行随后是其子算子如CopyCPU2CPU、_plus_scalr的执行顺序。关键注意点即使在符号式Symbolic模式下使用自定义算子也必须开启profile_imperativeTrue才能看到上述信息——因为自定义算子内部的纯 Python 代码与子算子依然是按命令式调用的。符号式等价代码如下# 方式一profile_all 全开 profiler.set_config(profile_allTrue, aggregate_statsTrue, continuous_dumpTrue) # 方式二显式同时开启 symbolic 与 imperative profiler.set_config(profile_symbolicTrue, profile_imperativeTrue, \ aggregate_statsTrue, continuous_dumpTrue) profiler.set_state(run) # 符号式模式 a mx.symbol.Variable(a) b mx.symbol.Custom(dataa, op_typeMyAddOne) c b.bind(mx.cpu(), {a: inp}) y c.forward() mx.npx.waitall() profiler.set_state(stop) print(profiler.dumps()) profiler.dump()需要注意的几条规则dump()与finished只要不打算结束 dump就应使用profiler.dump(finishedFalse)否则在模型运行中途调用profiler.dump()可能引发意外行为且之后若再调用profiler.set_config()会导致程序报错。只能 dump 到一个文件不要在模型运行中途用profiler.set_config(filenamenew_name.json)更换目标文件否则会产生不完整的 dump 输出。进阶配合 NVIDIA 剖析工具MXNet Profiler 是剖析 MXNet 代码的推荐起点但 NVIDIA 还提供了低层 CUDA 剖析工具NVProf、Visual ProfilerCUDA 9 / CUDA 10 工具包自带与Nsight ComputeCUDA 10 工具包自带可用于剖析运行在 CUDA 9 上的代码。它们可以剖析任意可执行程序因此也适用于运行 MXNet 的 Python 脚本并能与 MXNet Profiler 联合使用上层看 MXNet 的算子级信息下层看 CUDA kernel 级信息。NVProf 与 Visual Profiler从命令行用nvprof包裹 Python 脚本执行$ nvprof -o my_profile.nvvp python my_profiler_script.py输出类似11588 NVPROF is profiling process 11588, command: python my_profiler_script.py 11588 Generated result file: /home/user/Development/mxnet/ci/my_profile.nvvp生成的.nvvp文件会用 NVTX range对应 MXNet 算子标注与 NVProf 标准时间线一同展示便于建立“MXNet 算子 → CUDA kernel 调用”的映射关系。文件可用 Visual Profiler 打开时间线上方是 CPU 侧任务驱动操作、内存拷贝、MXNet 引擎算子调用、命令式 API 调用下方是同一时间段内 GPU 上活跃的 kernel。放大某个反向卷积算子可以看到它由多个 GPU kernel 组成如 cuDNN Winograd 卷积调用、FFT 调用点选任一 kernel 还能看到占用率与理论值的对比、共享内存使用量、执行时长等 GPU 性能指标。Nsight ComputeNsight Compute 不提供时间线视图但提供每个 kernel 的大量底层统计并支持多次运行对比例如建立 baseline。提示如果nvprof不在 PATH 中可以在 CUDA 安装目录下找到它。更多设置细节可参考 MXNet 官方讨论区。结语对异步执行的深度学习框架而言性能剖析必须依赖框架自身的 Profiler 而非外部计时器。通过mxnet.profiler的配置、状态控制、聚合统计与 Chrome Tracing 导出配合 bulk 模式开关与 oneDNN / NVIDIA 工具你可以精确定位训练与推理中的热点算子为后续优化指明方向。仓库中的 example/profiler 提供了矩阵乘法、NDArray 算子等可直接运行的剖析示例配合 tests/python/unittest/test_profiler.py 可以快速验证你对 Profiler API 的理解。【免费下载链接】mxnetLightweight, Portable, Flexible Distributed/Mobile Deep Learning with Dynamic, Mutation-aware Dataflow Dep Scheduler; for Python, R, Julia, Scala, Go, Javascript and more项目地址: https://gitcode.com/gh_mirrors/mxne/mxnet创作声明：本文部分内容由AI辅助生成（AIGC），仅供参考