PyTorchでのprofilerの使い方

#はじめに
ここでは、PyTorchで提供されているプロファイラの取り方について説明する。このため、CUDA関数のプロファイルの取り方等は、[別記事](https://qiita.com/sakaia/items/3082752b5cfcc19537eb)を参考してほしい。

#PyTorchコードに対してプロファイルを外部からとる
PyTorchスクリプトに対して、そのままプロファイルを取ることが出来る。Google Colaboratoryでも`%%writefile`で書き込めば、そのファイルに対して実行出来る。

```
python -m torch.utils.bottleneck /path/to/source/script.py [args]
```
以下の2種類のプロファイルを取得できる。autograd.profilerは、後で出てくるのでここでは述べない。

- [cProfiler](https://docs.python.org/ja/3/library/profile.html)
- torch.autograd.profiler.profiler

cProfilerは、Pythonから呼び出した関数毎に記録する仕組みである。なお、同じ名前の関数は、呼び出し回数と処理時間の加算だけで、まとめる。このため、呼出しごとにイベントを作成するautograd profilerよりメモリ消費量が小さい。
余談だが、cProfileそのものは、以下で取ることもできる。ソートオプションは、なくても良い。

```
python -m cProfile  -s tottime /path/to/source/script.py [args]
```


##　参考資料
- [TORCH.UTILS.BOTTLENECK](https://pytorch.org/docs/stable/bottleneck.html)
- ソースコード
  - `torch.utils.bottleneck`　
     - [run_autograd_prof](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/utils/bottleneck/__main__.py#L95) 
     - [run_cprofile](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/utils/bottleneck/__main__.py#L70)
     - [`__main__`](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/utils/bottleneck/__main__.py#L230)
- cProfileは、PythonインタープリターのCのコードで取っている。このため、Python関数の処理実行時間はわかるものの、逆伝搬関数は、backwardメソッドの延長でまとめて呼ばれるので個別の時間はわからない。なお、コードの入り口は、以下を参照。[(ソースコードメモ)Pythonのモジュール実行](https://qiita.com/sakaia/items/94686f71c24aa45909bb)
  - [Python プロファイラ](https://docs.python.org/ja/3/library/profile.html)
     - [Python関数を定義しているソースコード](https://github.com/python/cpython/blob/3.7/Modules/_lsprof.c#L800)


#PyTorchコード内でのプロファイルの取り方
torch.autograd.profiler.profileで順伝搬および逆伝搬のプロファイルを取ることが出来る。このため、cProfileに比べて、逆伝搬のプロファイルをより詳細に取得することが可能になる。

-  なお、以下のself_cpu_time_totalは、[1.1.0から加えられたオプション](https://github.com/pytorch/pytorch/commit/7a8bc85f478b11fde20525a717b7cc3a72a5a6b2)である。それ以外の指定では、cpu_time_total等を使うのが良い。
-  また、[1.2.0からは、テンソルシェープも取れるようになった。](https://github.com/pytorch/pytorch/commit/864cfbc2162a874fd67b50414205483cb9ac6b5d)


```
import torch
x = torch.randn((1, 1), requires_grad=True)
with torch.autograd.profiler.profile(use_cuda=True) as prof:
    for _ in range(100):  # any normal python code, really!
      y = x ** 2 
      y.backward()
print(prof)
print(prof.key_averages().table(sort_by="self_cpu_time_total"))      
```
なお、一つ一つのプロファイルを、表示する場合profオブジェクトをそのまま出力する。
そして、関数毎にまとめたい場合、prof.key_averages().table()を用いて出力する。
profオブジェクトの出力例は以下である。(関数毎表示であり長いので頭の部分だけ表示)

```
-----------------------------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------
Name                                 Self CPU total %   Self CPU total      CPU total %        CPU total     CPU time avg     CUDA total %       CUDA total    CUDA time avg  Number of Calls
-----------------------------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------
pow                                           23.43%         10.363ms           23.43%         10.363ms         10.363ms           23.49%         10.359ms         10.359ms                1
torch::autograd::GraphRoot                     0.03%         12.590us            0.03%         12.590us         12.590us            0.01%          4.096us          4.096us                1
PowBackward0                                  29.11%         12.876ms           29.11%         12.876ms         12.876ms           29.20%         12.878ms         12.878ms                1
pow                                           14.84%          6.566ms           14.84%          6.566ms          6.566ms           14.90%          6.571ms          6.571ms                1
```
prof.key_averages().table(sort_by="self_cpu_time_total")の出力例は以下である。なお、self_cpu_time_totalは、1.1.0から加えられたオプションであることに注意。(このため、1.1.0以降でないと動かない。)

```
-----------------------------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------
Name                                 Self CPU total %   Self CPU total      CPU total %        CPU total     CPU time avg     CUDA total %       CUDA total    CUDA time avg  Number of Calls
-----------------------------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------
torch::autograd::GraphRoot                    30.61%          2.595ms           30.61%          2.595ms         25.949us           22.90%          2.478ms         24.781us              100
pow                                           28.56%          2.422ms           28.56%          2.422ms         12.108us           20.32%          2.199ms         10.993us              200
mul                                           20.93%          1.775ms           20.93%          1.775ms          8.873us           15.90%          1.720ms          8.601us              200
PowBackward0                                  14.19%          1.203ms           45.82%          3.885ms         38.846us           36.37%          3.936ms         39.356us              100
torch::autograd::AccumulateGrad                5.71%        484.264us            5.71%        484.264us          4.843us            4.52%        488.902us          4.889us              100
-----------------------------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------  ---------------
Self CPU time total: 8.479ms
CUDA time total: 10.821ms
```
##仕組み
仕組みは、(Pythonで)torch.autograd.profilerから、(C++のコードである)torch::autograd::profiler名前空間にあるstate変数にプロファイルモードを指定(enableProfiler/disableProfiler)し、取得することにより実現している。profiler classの[`__enter__`および`__exit__`メソッド](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/autograd/profiler.py#L247)でわかる通り、稼働中はイベントをメモリに保持し、終了時にPython側の[profileクラスのfunction_events属性に出力する。](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/autograd/profiler.py#L263)
なお、イベントの構造体は、[(C++の)RangeEventList](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/csrc/autograd/profiler.h#L177)であり、recordメソッドで記録している。

##参考資料
+ [torch.autograd.profiler.profile](https://pytorch.org/docs/stable/autograd.html#torch.autograd.profiler.profile)
  + [key_averageメソッド] (https://pytorch.org/docs/stable/autograd.html#torch.autograd.profiler.profile.key_averages)
  + [tableメソッド](https://pytorch.org/docs/stable/autograd.html#torch.autograd.profiler.profile.table)
+ ソースコード
   + Python側
      + [class profile(object)](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/autograd/profiler.py#L190)
         + contextlib前提なので、`__init__`, `__enter__`, `__exit__`の3つのメソッドがポイント
   + C++側
      + [torch.autograd.profilerのC++へのマッピング](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/csrc/autograd/init.cpp#L21)
      + [プロファイル状態設定パラメータ](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/csrc/autograd/profiler.cpp#L23)
      + [struct RangeEventList](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/csrc/autograd/profiler.h#L177)(イベントを保持する構造体)
      + [getTime()](https://github.com/pytorch/pytorch/blob/v1.2.0/torch/csrc/autograd/profiler.h#L74)
         + CPU側は、CLOCK_MONOTONIC等で計測している。CUDA側は、cudaEventベース

+ 関連ソフトウェア資料
  + [(CUDA)5.5. Event Management](https://docs.nvidia.com/cuda/cuda-runtime-api/group__CUDART__EVENT.html#group__CUDART__EVENT)
     + CUDA側は、cudaEventSynchronize関数等で計測している。
  + [(Python)time — Time access and conversions](https://docs.python.org/3/library/time.html)


#ほかのフレームワークでの測定方法
## TensorFlowの場合
以下のように、デバイス(GPU/CPU)を指定して作成する。

```
%%writefile topk.py
import tensorflow as tf
from tensorflow.python.client import timeline

tf.set_random_seed(0)
with tf.device("/GPU:0"):
    x = tf.random_normal([32*8732])
    y, idxes = tf.nn.top_k(x, k=8732*32)

run_options = tf.RunOptions(trace_level=tf.RunOptions.FULL_TRACE)
run_metadata = tf.RunMetadata()
    
with tf.Session(config=tf.ConfigProto(log_device_placement=True)) as sess:
    sess.run(y,
                         options=run_options,
                         run_metadata=run_metadata) 

step_stats = run_metadata.step_stats
tl = timeline.Timeline(step_stats)

# Tensorの利用メモリもshow_memory=Trueでとれるが割愛
ctf = tl.generate_chrome_trace_format(show_memory=False,
                                      show_dataflow=True)

with open("timeline.json", "w") as f:
  f.write(ctf)
```
nvprofと一緒にプロファイルをとる。nvprofは、libcudartレベルの測定である。一方timelineは、TensorFlowのOpレベルの測定である。このためフレームワークのオーバヘッドが余分にかかる。

```
!nvprof python3 topk.py
```
プロファイルデータを出力する。なお、まとめてみたい場合、grepを使うと良いかもしれない。

```
!cat timeline.json | grep -e name -e dur
```
ここで、durが、マイクロ秒単位の時間である。

```
        {
            "ph": "X",
            "cat": "Op",
            "name": "TopKV2",
            "pid": 1,
            "tid": 0,
            "ts": 1560516999982492,
            "dur": 1315,
            "args": {
                "name": "TopKV2",
                "op": "TopKV2",
                "input0": "random_normal/RandomStandardNormal",
                "input1": "TopKV2/k"
            }
        },
```