自分への備忘録的な意味も込めて最近まとめたので、私が実践しているChainer/ChainerMNのプロファイルの取り方とプロファイル結果の見方を紹介します。
この記事で使うプロファイラは、Chainerのプロファイルを取る際まず取るべきと思われるcProfileとnvprofの二つです。
環境
- Python: 3.6
- Chainer: 5.2
- CuPy: 5.2
- CUDA: 9.0
- MPI: OpenMPI 1.10.7
参考コード
この記事ではChainerMNのmnistのサンプルをベースに改造したコードで説明を行っています。
mnistのオリジナルのコードはこちら。
https://github.com/chainer/chainer/blob/v5/examples/chainermn/mnist/train_mnist.py
改良後のコードはここに上げてあります。
https://github.com/shu65/chainermn_mnist/blob/master/train_mnist_with_benchmark.py
プロファイルを取りやすいコードのポイント
プログラムの高速化をする上で、プロファイルの取得は不可欠なため、修正するたびに何度も取る必要があります。
このため、簡単にプロファイルを取れるように、いつも以下のようなコードを追加しています。
1．benchmarkモードを追加し、通常の学習とは違い短いiterationsで終わるようにする
通常の学習とは別に、引数で切り替えられるbenchmarkモードを作っておくと、学習モードとは切り分けたコードを書くのことができて便利です。
また、benchmarkモードのとき、iteration数を変更できるようにしておくと、cProfileとnvprofそれぞれに合わせたiteration数でプロファイルが取れるので楽です。
コードとしては以下のようなイメージになります。
# 引数の追加
parser.add_argument('--benchmark', action='store_true',
help='benchmark mode')
parser.add_argument('--benchmark-iteration', type=int, default=500,
help='the number of iterations when using benchmark mode')
# benchmarkモードによるiteration数を変更
if args.benchmark:
stop_trigger = (args.benchmark_iteration, 'iteration')
else:
stop_trigger = (args.epoch, 'epoch')
trainer = training.Trainer(updater, stop_trigger, out=args.out)
mnistの場合は1 epochがすぐ終わるので気にならないのですが、ImageNetなどの大きいデータの場合、1 epochでも非常に長いため、benchmarkモードのときだけ学習の長さをiterationで指定できるようにすると便利です。
今回の例示で用いているのはmnistなのでそれほど必要ではありませんが、 上記の例では参考になるようにbenchmarkモードのとき、iteration数を指定できる --benchmark-iteration を追加しています。
2．cProfileでプロファイルを取る--cprofileの追加
cprofileを取るかどうかを以下のように引数で切り替えられるようにしています。
# 引数の追加
parser.add_argument('--cprofile', action='store_true', help='cprofile')
主に時間のかかるのは Trainer.run() の中なので、この部分だけプロファイルをとるようにしています。
if args.cprofile:
pr = cProfile.Profile()
pr.enable()
trainer.run()
if args.cprofile:
pr.disable()
s = io.StringIO()
sort_by = 'tottime'
ps = pstats.Stats(pr, stream=s).sort_stats(sort_by)
ps.print_stats()
if comm.rank == 0:
print(s.getvalue())
pr.dump_stats('{0}/rank_{1}.cprofile'.format(args.out, comm.rank))
rank 0のプロファイル結果はぱっと確認できるように標準出力にも出力しています。
また、MPIのrank別にプロファイルを出力すると、MPIのrank別にどれくらいばらつきがあるかも確認できるのでお勧めです。
実際のプロファイルの取り方
改良を加えたコードを使ってどのようにプロファイルを取るか説明していきます。
cProfile
上記のポイントの通り改造してあると、以下のように実行することでcProfileによるプロファイル結果が簡単にとれます。
$ mpiexec -n 4 python train_mnist_with_benchmark.py -g --benchmark --cprofile
実行結果は以下のような感じです。
$ mpiexec -n 4 python train_mnist_with_benchmark.py -g --benchmark --cprofile
==========================================
Num process (COMM_WORLD): 4
Using GPUs
Using hierarchical communicator
Num unit: 1000
Num Minibatch-size: 100
Num epoch: 20
==========================================
epoch main/loss validation/main/loss main/accuracy validation/main/accuracy elapsed_time
1 0.281213 0.105471 0.918133 0.9679 11.9005
2 0.0869378 0.0882739 0.973467 0.9724 13.119
3 0.0542736 0.0749994 0.984 0.9767 14.3335
2346179 function calls (2311141 primitive calls) in 14.774 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
22 9.019 0.410 9.019 0.410 {built-in method cupy.cuda.nvrtc.compileProgram}
575 0.800 0.001 0.800 0.001 {cupy.cudnn.softmax_forward}
998 0.620 0.001 0.620 0.001 {method 'Alltoall' of 'mpi4py.MPI.Comm' objects}
...
また、rank別に以下のように出力ファイルができています。
$ ls -al result/*cprofile
-rw-rw-r-- 1 ssuzuki ssuzuki 85346 Feb 4 11:59 result/rank_0.cprofile
-rw-rw-r-- 1 ssuzuki ssuzuki 78564 Feb 4 11:59 result/rank_1.cprofile
-rw-rw-r-- 1 ssuzuki ssuzuki 78564 Feb 4 11:59 result/rank_2.cprofile
-rw-rw-r-- 1 ssuzuki ssuzuki 78564 Feb 4 11:59 result/rank_3.cprofile
nvprof
nvprofのほうも上記のポイントの通りコードを作っておくと以下のように簡単に取れます。
$ mpiexec -n 4 nvprof -o %h-%p.nvprof python train_mnist_with_benchmark.py -g --benchmark --benchmark-iteration 50
実行結果は以下のような感じです。
$ mpiexec -n 4 nvprof -o %h-%p.nvprof python train_mnist_with_benchmark.py -g --benchmark --benchmark-iteration 50
==========================================
Num process (COMM_WORLD): 4
Using GPUs
Using hierarchical communicator
Num unit: 1000
Num Minibatch-size: 100
Num epoch: 20
==========================================
==14874== NVPROF is profiling process 14874, command: python train_mnist_with_benchmark.py -g --benchmark --benchmark-iteration 50
==14869== NVPROF is profiling process 14869, command: python train_mnist_with_benchmark.py -g --benchmark --benchmark-iteration 50
==14875== NVPROF is profiling process 14875, command: python train_mnist_with_benchmark.py -g --benchmark --benchmark-iteration 50
==14871== NVPROF is profiling process 14871, command: python train_mnist_with_benchmark.py -g --benchmark --benchmark-iteration 50
epoch main/loss validation/main/loss main/accuracy validation/main/accuracy elapsed_time
==14875== Generated result file: ***/chainermn_mnist/host0-14875.nvprof
==14871== Generated result file: ***/chainermn_mnist/host0-14871.nvprof
==14874== Generated result file: ***/chainermn_mnist/host0-14874.nvprof
==14869== Generated result file: ***/chainermn_mnist/host0-14869.nvprof
(*一部出力を隠しています)
実行後は以下のように出力ファイルができています。
$ ls -al ./*.nvprof
-rw-r--r-- 1 ssuzuki ssuzuki 3209216 Feb 4 12:04 ./host0-14869.nvprof
-rw-r--r-- 1 ssuzuki ssuzuki 2046976 Feb 4 12:04 ./host0-14871.nvprof
-rw-r--r-- 1 ssuzuki ssuzuki 2046976 Feb 4 12:04 ./host0-14874.nvprof
-rw-r--r-- 1 ssuzuki ssuzuki 1929216 Feb 4 12:04 ./host0-14875.nvprof
nvprofの注意点
nvprofのほうは実行するとき、以下の点を注意する必要があります。
- ChainerMNを使う場合は必ず出力ファイルを
-oで指定する。 - iteration回数は少なくする
まず、1についてですが、nvprofの出力結果をMPIのrank毎に別々のファイルに書き出すようにする必要があります。別々のファイルであればどのような名前でも良いのですが、上記の実行方法では、${host名}-${プロセスID}.nvprofの名前でファイルを出力しています。
また、2はChainer/ChainerMN共通の注意点です。iteration数が多すぎるとnvprofの出力結果が大きくなり、nvprofの出力に時間がかかってしまいます。さらに、CUDAのプロファイルビューワーのnvvpで確認する際、nvvpが重くなります。このため、iteration数が多いとnvvpを使ってまともに確認できなくなります。この問題を回避するために、iteration数は少なめにすると良いです。nvvpで見ることが前提であれば50 iterationもあれば十分かと思います。
プロファイル結果の見方
cProfile、nvprofの結果を確認するときはGUIを使って見るほうが何かとわかりやすいのでお勧めです。
私はそれぞれ以下のものを使っています。
cprofileの場合：snakeviz
https://jiffyclub.github.io/snakeviz/
nvprofの場合：nvvp
https://developer.nvidia.com/nvidia-visual-profiler
ただし、Chainer/ChainerMNのプロファイル結果を見て解釈するときは以下のような注意点があります。
1. cProfileだけで絶対に判断してはいけない
cProfileのほうが取るのも簡単だし、見るのも簡単なため、cProfileだけ取って確認するということをやりたくなります。
しかし、cProfileだけで判断しては絶対いけません。
なぜなら、cProfileの結果、ある関数に時間がかかっているように見えた場合でも、本当にその関数が遅いわけではないという場合があるためです。
これはCPUとGPUの同期が関係しています。
CPU側の計算とGPU側の計算は基本的に非同期です。
しかし、場合によってはCPUとGPUの同期が走ります。
この同期が発生した場合、そこまでに投入されたCUDAカーネルが全部実行されるのをCPUが待ちます。結果として、同期が走る関数はcProfileの結果としては時間のかかる関数のように見えてしまいます。
このため、cProfileの結果、時間のかかっているように見える関数が本当に遅いのか、それともCUDAの同期が走ったため遅く見えるだけなのか、cProfileとnvprofを両方見て判定する必要があります。
ちなみに、同期が走る条件はわかりやすいのはCUDAのnull streamに対してsynchronize()を呼んだ場合です。
ただ、他にもいくつか同期する条件があります。詳しくはCUDAのprogramming guideの以下のところに書いてありますので、詳しく知りたい人はそちらを参照してください。
https://docs.nvidia.com/cuda/cuda-c-programming-guide/index.html#explicit-synchronization
https://docs.nvidia.com/cuda/cuda-c-programming-guide/index.html#implicit-synchronization
2. マルチプロセスで実行されている関数はcProfileに出てこないことを意識しておく
Pythonの並列化ではマルチプロセスがよく使われます。ChainerでもMultiProcessIteratorを使うと内部でマルチプロセスによる並列化が行われます。
しかし、cProfileにはマルチプロセス内で実行した関数についてはプロファイルで出てきません。Chainerでいえば、MultiProcessIteratorに渡すDatasetクラスの関数に関してはプロファイル結果が取得できません。このため、Datasetクラスのプロファイルを取りたい場合は、別途micro benchmarkを書いてプロファイルを取るか、マルチプロセスを使わないSerialIteratorを使う必要があります。
3. --benchmark-iterationの値によってはプロファイルが取れていないExtensionがある
ポイントに従って改良した場合特有の話ですが、--benchmark-iterationで指定したiteration数が少ないとTrainerのExtensionのうち、1度も実行されずに学習が終わってしまうExtensionがでてしまう場合があります。頻繁に実行されないExtensionは気にしなくてもいい場合が多いですが、頻繁に実行されるExtensionや、何も気にして書いていない自作のExtensionは学習速度低下の原因になる場合があるので、benchmarkモードのときはExtensionのプロファイルが取られているのかどうか注意しておくと良いです。
プロファイルを取ったその後
プロファイルを取ってボトルネックがわかったら、あとはひたすら遅い部分を改良してプロファイルを取るということを繰り返します。
自分で書いた関数であれば「がんばってください」としか言えないですが、高速化するうえで参考になりそうなものとして以下のものがあります。
ハイパフォーマンスPython
https://www.amazon.co.jp/%E3%83%8F%E3%82%A4%E3%83%91%E3%83%95%E3%82%A9%E3%83%BC%E3%83%9E%E3%83%B3%E3%82%B9Python-Micha-Gorelick/dp/4873117402
Pythonのプロファイルの取り方や、高速化のやり方がいろいろ書いてある本です。Optimizing Deep Learning with Chainer@GTC Japan 2018
https://www.slideshare.net/pfi/gtcj2018-optimizing-deep-learning-with-chainerpfn
いくつかChainerの高速化Tipsが良くまとまっているスライドです。