MindSpore执行状态日志解析与应用

背景

MindSpore作为新一代深度学习框架，具有动态图灵活、易调试的特点，同时支持图模式执行，提高执行效率。动静结合的方式，加上多组件多后端，其执行流程较为复杂。尤其是静态图模式下，图编译与执行过程是一个黑盒，这给用户跟踪MindSpore执行状态，功能调试带来挑战。

特性简介

为解决跟踪MindSpore的执行状态，提出通过设计状态日志。 识别各组件的关键环节的起始与终止位置，记录状态信息日志，实现执行状态的跟踪。
MindSpore主要的执行流程包括图编译和图执行，其中图编译分为前端编译与后端编译。前端编译是与设备无关的语法解析与优化过程，后端编译是与设备相关的特化过程。

图编译的主要阶段包括如下：

• parse：负责解析入口函数，该阶段会初步生成MindIR，如果查看IR文件，我们能观察到该阶段仅仅解析了顶层Cell的图信息；

• symbol_resolve：负责进一步解析入口函数，主要是递归解析入口函数直接或间接引用到的其他函数和对象。如果使用了尚不支持的语法，一般会在此阶段出错；

• abstract_specialize：根据输入信息推导出IR中所有节点的数据类型和形状信息；

• optimize：负责硬件无关的优化，自动微分与自动并行功能也是在该阶段展开。该阶段又可细分为若干个子阶段，算子融合即是在该阶段；

• validate：负责校验编译出来的计算图，如果到此阶段计算图中还有仅临时使用的内部算子，则会报错退出；

• task_emit： 负责将计算图传给后端进行后端优化；

• execute：负责启动执行图流程。

为记录mindspore的编译与执行状态，在任务的开始与结束，计算图的编译与执行各阶段打印格式化日志信息。 格式如下：

Status record: system init.
Status record: start xxx action.
Status record: end xxx action.
...
Status record: start load input. xxx
Status record: end load input. xxx
Status record: start run graph. xxx
Status record: end run graph. xxx
...
Status record: system exit.

system init 表示C++后端初始化。

star xxx action 表示前端编译的各个阶段的开始，如start parse action,start symbol_resolve action等等。

end xxx action 表示前端编译的各个阶段的结束，与start xxx action成对出现。 如end parse action,end symbol_resolve action等。

start load input表示后端开始加载数据进行训练或推理，该信息后面的xxx表示附加说明信息，例如当前计算图的编号，当有多个计算图时，会分别记录多个计算图的起始状态。

end load input表示后端加载数据完成。 与start load input成对出现。附加说明信息中计算图的编号会保持一致，表示同一个计算图执行的开始与结束。

start run graph表示开始在设备上执行计算图。 附加说明信息中的计算图的编号会与加载数据的图对应。

end run graph 表示完成在设备上执行计算图。 与start run graph成对出现，附加说明信息中计算图的编号会保持一致，表示同一个计算图执行的开始与结束。

system exit 表示C++后端执行结束。

由于训练过程是一个循环执行，所以start load input, end load input，start run graph与end run graph 状态会打印多次，打印次数与训练的执行模式（是否图下沉）、step以及epoch有关。

在不同的后端图编译过程中，会记录不同的子阶段的执行状态，这些状态主要用于开发者定位问题，用户可以不用过多关注这些状态。

MindSpore执行状态日志级别是INFO，需要设置环境变量GLOG_v=1，并将执行日志落盘到文件，然后通过查询关键字Status record:筛选出执行状态日志。

例如，在CPU上使用mnist数据集训练lenet，获取执行状态日志的方法如下：

1、设置环境变量，指定日志打印级别为INFO：

export GLOG_v=1

2、执行训练任务，指定数据集路径$DATA_PATH和保持checkpoints路径$CKPT_PATH，并落盘日志到文件:

python train.py --data_path=$DATA_PATH --device_target="CPU" --ckpt_path=$CKPT_PATH > log.txt 2>&1 &

3、通过关键字筛选执行状态日志：

grep "Status record:" log.txt > status.txt

如下是CPU上的执行状态日志：

Status record: system init.
Status record: start parse action.
Status record: end parse action.
Status record: start symbol_resolve action.
Status record: end symbol_resolve action.
Status record: start combine_like_graphs action.
Status record: end combine_like_graphs action.
Status record: start inference_opt_prepare action.
Status record: end inference_opt_prepare action.
Status record: start abstract_specialize action.
Status record: end abstract_specialize action.
Status record: start auto_monad action.
Status record: end auto_monad action.
Status record: start inline action.
Status record: end inline action.
Status record: start py_pre_ad action.
Status record: end py_pre_ad action.
Status record: start pipeline_split action.
Status record: end pipeline_split action.
Status record: start optimize action.
Status record: end optimize action.
Status record: start py_opt action.
Status record: end py_opt action.
Status record: start auto_monad_reorder action.
Status record: end auto_monad_reorder action.
Status record: start eliminate_forward_cnode action.
Status record: end eliminate_forward_cnode action.
Status record: start validate action.
Status record: end validate action.
Status record: start task_emit action.
Status record: end task_emit action.
Status record: start execute action.
Status record: end execute action.
Status record: start load input. graph id: 0
Status record: end load input. graph id: 0
Status record: start run graph. graph id: 0
Status record: end run graph. graph id: 0
Status record: start load input. graph id: 0
Status record: end load input. graph id: 0
Status record: start run graph. graph id: 0
Status record: end run graph. graph id: 0
...
...
Status record: system exit.

应用示例

MindSpore执行状态日志方便用户识别当前任务的状态。当出现报错时，可以快速识别出当前的故障模块，有针对性地解决问题。 此外，在多机多卡并行训练的场景下，如果不同进程之间存在执行不同步的问题，用户可以利用执行状态日志快速识别执行慢的结点或进程。 下面通过多进程并行训练场景的故障分析，说明在并行训练场景下状态日志的应用。

场景1 进程意外终止，无system exit状态日志

单机多进程训练场景，一个进程在参数更新阶段会等待其他进程返回梯度信息。当某个进程意外终止退出时，其他进程因等待超时而报错。意外终止进程的INFO日志不会打印退出状态Status record: system exit。 使用grep命令搜索Status record: system exit，如果某进程日志不包含该条日志信息，则该进程为异常终止进程，其他进程执行异常由异常终止进程引起。此时，分析线程异常终止的原因即可，如原因不明，可重启训练任务。

场景2 进程退出不同步

多机多进程训练场景，存在一个执行慢的节点。常见的故障场景时编译期不同步，如扩容场景下，新增节点没有编译缓存，其他旧节点存在编译缓存，没有编译缓存的节点会进行图编译，速度慢。有编译缓存的节点直接读取编译缓存，速度快。在所有节点的日志中，使用grep命令搜索Status record: system exit，每个节点中每个进程的INFO日志都会包含退出状态信息，比较退出状态信息的时间，可以找出退出最早和最晚的进程。退出时间相差500s左右时，可确定晚退出的节点是故障节点。需要注意的是，不同节点的系统时间可能存在差异，需要消除时间基准不同引起的时间差异。 消除差异的方法，可以计算Status record: system exit 与Status record: system init的时间差，时差最长的节点即为故障节点。