本チュートリアルでは、設計したニューラルネットワークの学習、認識に要する処理時間（wall clock time）を詳細に測定するProfiling機能についてご紹介します。本機能を用いることで、学習時のレイヤー毎、Forward/Backward計算毎の処理時間に加え、学習時の各レイヤーにおける処理の実行順、各レイヤーの処理に用いられている実装も合わせて確認することが可能です。
Profilingの準備
まずNeural Network Consoleを通常通り使用して、プロジェクトファイルを測定対象のニューラルネットワークが学習可能な状態にします。今回はサンプルとして、Neural Network Consoleのサンプルプロジェクトに含まれているLeNetサンプルプロジェクトを用います。
\samples\sample_project\image_recognition\MNIST\LeNet.sdcproj
LeNetサンプルプロジェクト
Profilingの実行
プロジェクトを読み込んだら、学習実行ボタンを右クリックして表示されるポップアップメニューから「Profile」を選択します。
Profilingの実行
もし学習が正しく実行できない状態である場合はここでエラーが表示されますので、エラーメッセージに従ってネットワークの構成やデータセットの設定を見直します。
正しくProfilingがスタートすると、学習ログの代わりに以下のようなログが出力されます。
| load_dataset 2.692669(ms) let_data (x to Input) 0.288460(ms) let_data (y to CategoricalCrossEntropy_T) 0.303508(ms) setup_function (Convolution : Convolution) 0.005436(ms) setup_function (ReLU : ReLU) 0.003144(ms) setup_function (MaxPooling : MaxPooling) 0.003172(ms) setup_function (Convolution_2 : Convolution) 0.003984(ms) setup_function (MaxPooling_2 : MaxPooling) 0.004164(ms) setup_function (Tanh_2 : Tanh) 0.003220(ms) setup_function (Affine : Affine) 0.003720(ms) setup_function (ReLU_2 : ReLU) 0.003057(ms) setup_function (Affine_2 : Affine) 0.003823(ms) setup_function (Softmax : Softmax) 0.002936(ms) setup_function (CategoricalCrossEntropy : CategoricalCrossEntropy) 0.003911(ms) forward_function (Convolution : Convolution) 8.480232(ms) forward_function (ReLU : ReLU : in_place) 2.238630(ms) forward_function (MaxPooling : MaxPooling) 2.542305(ms) forward_function (Convolution_2 : Convolution) 5.676037(ms) forward_function (MaxPooling_2 : MaxPooling) 0.862022(ms) forward_function (Tanh_2 : Tanh) 0.087367(ms) forward_function (Affine : Affine) 0.642076(ms) forward_function (ReLU_2 : ReLU : in_place) 0.072308(ms) forward_function (Affine_2 : Affine) 0.030612(ms) forward_function (Softmax : Softmax) 0.011287(ms) forward_function (CategoricalCrossEntropy : CategoricalCrossEntropy) 0.004772(ms) prepare_backward 0.010244(ms) backward_function (CategoricalCrossEntropy : CategoricalCrossEntropy) 0.007124(ms) backward_function (Softmax : Softmax) 0.007879(ms) backward_function (Affine_2 : Affine) 0.061124(ms) backward_function (ReLU_2 : ReLU : in_place) 0.036198(ms) backward_function (Affine : Affine) 1.232067(ms) backward_function (Tanh_2 : Tanh) 0.015357(ms) backward_function (MaxPooling_2 : MaxPooling) 0.084125(ms) backward_function (Convolution_2 : Convolution) 10.869265(ms) backward_function (MaxPooling : MaxPooling) 0.243760(ms) backward_function (ReLU : ReLU : in_place) 1.690292(ms) backward_function (Convolution : Convolution) 6.254087(ms) forward_all 19.351335(ms) backward_all 21.065874(ms) backward_all(wo param zero_grad) 22.238991(ms) update (Adam) 0.103355(ms) monitor_loss 0.185341(ms) Profile Completed. |
Profiling結果のログ出力例
ログの解釈
以下で出力されたログについて解説していきます。ログに表示されている時間はすべて、Minibatchで指定したデータ数を処理するのに要した時間（ms単位）を示します。
Load dataset
ストレージからデータセットを読み出すのに要した時間を示します。
Let data
読みだしたデータセットを、NNablaエンジンに受け渡すのに要した時間を示します。カッコ内は、代入元と代入先が(データセット中の変数名 to NNablaのVariable名)であることを示します。
Generate data
上記ログには登場しませんが、ネットワークがGenerator（信号生成）を含む場合、そのデータの生成とNnablaのVariableへの代入に要した時間を示します。
Setup function
各レイヤーの初期化に要した時間を示します。カッコ内は、(Neural Network Console上のレイヤー名（レイヤーのNameプロパティの値） : 演算に用いられるNNablaのクラス名)を示します。GPU（CUDA、cuDNN）を用いている場合、NNablaのクラス名にCudaもしくはCudaCudnnが含まれるため、ネットワーク中の全てのレイヤーの処理がGPUで行われているかどうかについてもここで確認することが可能です。初期化は学習開始時に一度だけ行われるため、ここで表示される値が全体の計算時間に及ぼす影響は軽微です。
Forward function
各レイヤーのForward計算に要した時間を示します。「: in-place」が含まれているレイヤーは、メモリ節約のためNNablaのVariableを入出力で共有していることを示します。また、Forward functionがログに現れる順序を参照することで、学習中の実際のForward計算の順序を確認することができます。
Prepare backward
ネットワークのBackward計算の前処理に要した時間を示します。
Backward function
各レイヤーのBackward計算に要した時間を示します。ログの書式はForward functionと同様です。
Forward_all
ニューラルネットワークの入力からロス関数までForward計算を行うのに要した合計時間を示します。Forward functionとは別に全体の速度を測定するため、Forward functionで表示される時間の合計とは一致しない可能性があります。
Backward_all
ニューラルネットワークのロス関数からパラメータまでBackward計算を行うのに要した合計時間を示します。(wo param zero_grad)は、Backward計算のうち、パラメータの微分を保持するバッファ領域を0で初期化する時間を除いた場合の値です。
Weight decay
上記ログには登場しませんが、OptimizerのConfigでWeight decay（L2正則化）を指定した場合、ネットワーク中の学習対象に指定されている全てのパラメータについてWeight decayの演算に要した時間を示します。
Update
ネットワーク中の学習対象に指定されている全てのパラメータについてパラメータのUpdateの演算に要した時間を示します。カッコ内はパラメータ更新に用いられるNNablaのSolverのクラス名を示します。
Monitor loss
ロス関数の出力値をLearning Curveとしてモニターするために読み出す処理に要した時間を示します。
Profiling結果のグラフ化（Windows版のみ）
学習結果の出力フォルダにCSV形式で保存されているProfiling結果を利用することで、Profiling結果をより詳しく分析することができます。学習結果の出力フォルダを開くには、TRAININGタブの学習結果をダブルクリックするか、右クリックして表示されるメニューから「Open Result Location」を選択します。
学習結果の出力フォルダを開く
Profiling結果は学習結果の出力フォルダにあるprofile.csvに出力されています。例えばprofile.csvをExcelで開き、Forward function～Backward functionの処理時間に条件付き書式を設定することで、以下のような処理時間のVisualizeが可能です。
Forward～Backward処理に要した時間のVisualize例
