近所を散歩していたら、もう梅が咲いていました。今日は立春だそうです。早いなー。
わたしは梅のつぼみが大好きなので、これからはしばらく目が離せない日々が続きそうです。
前回のおさらい
前回得た結果は、「CPUとGPUを同時に使うより、GPUだけを使う方が実は倍ぐらい速い！」という、これまた逆説的な結果でした。
未改造のPyritでは「CPUとGPUを同時」に使うか、「CPUだけ」を使うかなので、なまじ「同時」が「CPUだけ」よりは速いが故に、そんな単純な事にも気づかなかった、と。
うーん…なんでこんな事に…。GPUを追加で使うぶんだけ、せめてちょびっとでも性能が向上してほしかったんですが…。
Pythonのコードのプロファイルを取ろう
これまでにCUDAコードのプロファイルを二回ほど取りました(一回目、二回目)が、今日はPythonのコードのプロファイルを取りましょう。もちろんPythonはCPUで実行されるわけですが、さらにPythonは高々１つのスレッドでしか同時に動作しないのでした。
今回Pythonのプロファイルを取ろうと画策するのは、次の観察からです：
- 2CPU、48コアを全部ぶん回すと48倍の性能がでない。htopを観察する限り、かといってCPUを全部使っているわけでもなさそう
- Pythonの１コアが各コアに仕事を分配しきれていないと考えると説明できます（わかんないけどね）
- GPUだけを使うにしても、GPUは使い切っていなさそう
- ここがよくわからない。GPUが消費しきる分のパスワードは生成できそうなので。
- ダミーパスワードの生成に何割くらい掛けているのかが気になる
というわけでモリモリ取っていきまっしょい。プロファイルのためのツールは公式で提供されていて、cProfileというのを使えば良さそうです。
% python -m cProfile -s tottime <実行ファイル名> <args...>
とやると、関数の内部の実行に掛かった順番でソートされた結果が帰ってきます。tottimeは、関数の中で他の関数を呼び出した時間は除いた、その関数の純粋な実行時間。cumtimeと入れると、その関数から呼び出した関数の時間も含まれます。
例えば、CPUを１コアだけ使った時の表示はこんな感じになります：
(venv) server01@server01:~/src/Pyrit$ time python2.7 -m cProfile -s tottime ./pyrit benchmark
Pyrit 0.5.1 (C) 2008-2011 Lukas Lueg - 2015 John Mora
https://github.com/JPaulMora/Pyrit
This code is distributed under the GNU General Public License v3+
Running benchmark (985.4 PMKs/s)... -
Computed 985.36 PMKs/s total.
#1: 'CPU-Core (SSE2/AES)': 1045.2 PMKs/s (RTT 2.8)
79276 function calls (78919 primitive calls) in 69.771 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1604 68.890 0.043 68.890 0.043 {time.sleep}
1963 0.514 0.000 0.514 0.000 {method 'acquire' of 'thread.lock' objects}
1 0.158 0.158 0.197 0.197 cpyrit.py:29(<module>)
1 0.094 0.094 69.571 69.571 pyrit_cli.py:1184(benchmark)
51 0.028 0.001 69.438 1.362 threading.py:309(wait)
54392 0.011 0.000 0.011 0.000 {method 'random' of '_random.Random' objects}
...（略）...
real 1m9.902s
user 1m9.087s
sys 0m0.302s
ログの一番上の行を見ることで、time.sleepで68.9秒とたくさん時間を使っていること、次に使っているのがacquireメソッドであること、がわかります。
さらに、
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.094 0.094 69.571 69.571 pyrit_cli.py:1184(benchmark)
real 1m9.902s
この二行を見ると、このベンチマークを実際に実行するbenchmark関数が69.5秒使っていること、処理時間が69.9秒で、その前後の初期化などに0.4秒ぐらい使われていること（まぁ、予想通りですよね）、などがわかりますよー、と。
この２つの情報を合計すると、CPUを１コアだけ使った時は、69.5秒中68.9秒、ほとんどtime.sleepで時間を潰していること（１コアのCPUが処理するのを待っていること）がなんとなくわかります。
以下前回みたく条件を変えて実行してみましたが、だらだらログを並べても中々わかりにくいので、表にしてみました：
| 条件 | 1番時間を使っている関数 （全処理に占める割合） | 2番時間 | 3番時間 | 4番時間 |
|---|---|---|---|---|
| 1cpu/0gpu | {time.sleep} (99.0%) | {method ‘acquire’ of ‘thread.lock’ objects} (0.7%) | cpyrit.py(<module>) (0.2%) | pyrit_cli.py(benchmark) (0.1%) |
| 48cpu/0gpu | {time.sleep} (92.0%) | {method ‘acquire’ of ‘thread.lock’ objects} (4.5%) | pyrit_cli.py(benchmark) (2.21%) | cpyrit.py(<module>) (0.22%) |
| 0cpu/4gpu | pyrit_cli.py(benchmark) (61.3%) | {method ‘flush’ of ‘file’ objects} (14.6%) | {method ‘acquire’ of ‘thread.lock’ objects} (12.4%) | cpyrit.py(dequeue) (4.04%) |
| 48cpu/4gpu | {method ‘acquire’ of ‘thread.lock’ objects} (65.2%) | pyrit_cli.py:1184(benchmark) (16.5%) | cpyrit.py(dequeue) (5.0%) | {time.sleep} (3.8%) |
だいたい上位に並ぶのはどれも同じ顔ぶればかりなのですが、下のほうに行けばいくほど、つまり、たくさんのCPUやGPUが仕事を要求するようになればなるほど、sleepよりも{method ‘acquire’ of ‘thread.lock’ objects}の処理時間がガンガン増えていく事がわかります。一番下の一番処理を取り合っているところではなんと6割もロックにつぎ込んでいます。これじゃあ、GPUのパスワードのクラックではなく、ロックを取り合うプログラムを実行していたと言っても過言ではありませんな。
そしてdequeue関数の処理内容が増えていくのも気になりますねぇ。この関数は、生成したパスワードをCPUやGPUが受け取るためのもので、threading.Conditionを使ってマルチスレッドの調停を行っております。
この２つから予想されることは、…おそらくこのthreading.Conditionオブジェクトの中にあるロックを取り合ってるんでしょうね…。
あまりにも闇が深そうなので今日はこのぐらいにしておきましょう。
GPUだけを使っているケース（三行目）については追加でコメントさせてください。benchmark関数が一番時間を使っていることから、一生懸命処理するためのパスワードを用意していることはなんとなく察されるのですが、パスワードの生成に使っているはずのrandom関数がリストアップされてこなくて、そのかわりにfile.flushが二番目に食い込んでいます。このflushはCUDA関係っぽい気がしますが、謎です。もうちょっと追いかける価値があると思います。
まとめ
- 仕事を要求するスレッドが増えれば増えるほど、仕事を用意するスレッドはsleepではなくlockの取り合いで時間を潰すようになる
- １つのロックを取り合ってそう
- GPUだけで処理しているときはパスワードの生成を頑張るみたいだが、実態は要調査
- 外へ出ろ、梅の花を見ろ！
今月は低電力モードとなっております。寒いからね、仕方ないね（ごめんなさい）。
株式会社Link-U 技術ブログ 