データセンターで偶然出会った、キーボード・No.1さんです。ナンバーワンですって。
まさか、こんなところでキーボード界の頂点に出会えるとは。偶然てのは、すごいですね。
キーボードを見る目のないわたしには、この方を見てもその凄さ−《王者の風格》、とでも言うべきものでしょうか−そういったものは、感じ取れませんでした。「能ある鷹は爪を隠す」ってやつなんでしょうか。いやぁ、御見逸れ致しました。わたくしにはキーボードの才能が無いのでしょう。わたしはせいぜい、指でキーボードぺちぺちする身で一生甘んじていようと思います。
キーボードのNo.1ってどうやって決めるんだろうとか、次の世界大会はいつなのかとか、聞けば良かったな。サインももらえば良かったかも。
…
…えー、もちろん嘘で、ただの通し番号です。データセンターにはたくさん共用のキーボードがあって空いてるものを番号の小さいものから貸してもらえるんですが、同時に作業する人は居ないのでいつもだいたいこのキーボードを貸してもらって作業しています。でも不思議かな、みんなこのキーボードばっかり使ってるはずなのに、「キーボードNo.10」とかの方がボロボロな感じがします。…もしかして、やっぱ世界１位《ザ・トップ・オブ・キーボード》だったのか？
いや…まさかね。
前回までのPyritなのですよ
えー、何の話でしたっけ。あーそうそう。無線LANのパスワード認証方式WPA2-PSKをPyritでクラックしてたんだけど、WPA2の仕様書が読めないから諦めて直接Pyritのソースを読んでいたんでしたね。
えー、何の話でしたっけ。あーそうそう。無線LANのパスワード認証方式WPA2-PSKをPyritでクラックしてたんだけど、WPA2の仕様書が読めないから諦めて直接Pyritのソースを読んでいたんでしたね。
簡単におさらいです：
- IteratorとCrackerというのがいて
- 辞書ファイルから読んだパスワードのリストを、Iteratorがresultsにして
- Crackerがresultsを検証して「そのパスワード、あたりっ！」「はずれっ！」と判定する
- CUDAを使っているのはIteratorだけ。CrackerはCPUでしか動かない。
というのを前回ソース読んで確認したんでした。
そもそも何を測っているのかを把握するのですよ
太古の昔に書いた最初の記事では、Pyritの「benchmark」というコマンドを実行してCPUと比較してみたり、GPU同士で比較して「Tesla V100はGTX1080よりめっちゃ高くて性能いいはずなのに大差ない…」とか嘆いていたわけですが、そもそもこれは何を測っていたのでしょうか。前回多少なりともソースコードを読んだ事により、このような多少深まった疑問が生まれるわけですな。前回見た限り、Crackerも二種類あって、データやコマンドラインフラグによって変わるんですよね。その辺の条件は？
…というわけで、早速読んでみましょう。pyritコマンドのサブコマンドの実装は全部ルートにあるpyrit_cli.pyに置いてありまして、コマンド名と関数名はすべて一致しています。つまり、benchmarkコマンドもbenchmark関数に置いてあります。大変わかりやすい。
ちょっと長いですが、多少はしょりつつ載せます：
def benchmark(self, timeout=45, calibrate=10):
# ... 略 ...
# ダミーの仕事をなげまくる仕事
t = time.time()
perfcounter = cpyrit.util.PerformanceCounter(timeout + 5)
while time.time() - t < timeout:
pws = ["barbarbar%s" % random.random() for i in xrange(bsize)]
cp.enqueue('foo', pws)
r = cp.dequeue(block=False)
# ... 略 ...
# CPUの結果を表示する
for i, core in enumerate(cp.cores):
if core.compTime > 0:
perf = core.resCount / core.compTime
else:
perf = 0
if core.callCount > 0 and perf > 0:
rtt = (core.resCount / core.callCount) / perf
else:
rtt = 0
self.tell("#%i: '%s': %.1f PMKs/s (RTT %.1f)" % \
(i + 1, core.name, perf, rtt))
# ... 略 ...
# GPUの結果を表示する
for i, CD in enumerate(cp.CUDAs):
if CD.compTime > 0:
perf = CD.resCount / CD.compTime
else:
perf = 0
if CD.callCount > 0 and perf > 0:
rtt = (CD.resCount / CD.callCount) / perf
else:
rtt = 0
self.tell("#%i: '%s': %.1f PMKs/s (RTT %.1f)" % \
(i + 1, CD.name, perf, rtt))
# ... 略 ...
cpyrit.cpyrit.CPyrit() as cp というのはIteratorが依存している、パスワードを入れるとresultsというリストが出て来るモジュールでした（で、これをCrackerがチェックする）。
すぐに気がつくのは、CPUやCUDAごとにベンチマークしてるわけではないことです。cp.enqueueとして「パスワード計算してくれや」とお願いすると、cpくんが代理店となって、実際にCPU、CUDA（、OpenCL）のどれで計算するかを決めるようになっています。で、あとで集計するときにcpくんに「ところでTesla使ったのってどれくらい？」って聞いて、その結果をベンチの結果としてまとめる、と。
うーん。APIとしてはバックエンドが隠蔽されてて、いい感じだと思います。でも、これで本当に「公平」にベンチマークできているのかは、若干怪しい感じがするんですが…。
とりあえず。前回、「CPUだけで走るCrackerがボトルネックとなってbenchmarkでTeslaがあんまり速くなかったのでは？」という仮説を立てましたが、それは否定されました。だって、見ての通り、Crackerは走らないからです。もちろん、「このbenchmarkでは」であって、実際にパスワードを検索する時はCrackerも走らせて正しいパスワードかどうかチェックするので、Crackerがボトルネックとなる可能性は残ります。
綺麗なCUDAプロファイラーでも眺めるのですよ
なんか手詰まり感があるので、ここで一旦ソースコードの調査を打ち切ってプロファイラーで遊んでみましょう。
というのも。
ベンチマーク取ってる間、nvidia-smiコマンドを打つとこんな感じで消費電力が見れるわけですが：
+-----------------------------------------------------------------------------+ | NVIDIA-SMI 390.30 Driver Version: 390.30 | |-------------------------------+----------------------+----------------------+ | GPU Name Persistence-M| Bus-Id Disp.A | Volatile Uncorr. ECC | | Fan Temp Perf Pwr:Usage/Cap| Memory-Usage | GPU-Util Compute M. | |===============================+======================+======================| | 0 Tesla V100-PCIE... Off | 00000000:3D:00.0 Off | 0 | | N/A 55C P0 43W / 250W | 0MiB / 16160MiB | 0% Default | +-------------------------------+----------------------+----------------------+ | 1 Tesla V100-PCIE... Off | 00000000:3E:00.0 Off | 0 | | N/A 57C P0 45W / 250W | 0MiB / 16160MiB | 0% Default | +-------------------------------+----------------------+----------------------+ | 2 GeForce GTX 108... Off | 00000000:B1:00.0 Off | N/A | | 28% 50C P0 60W / 250W | 0MiB / 11178MiB | 0% Default | +-------------------------------+----------------------+----------------------+ | 3 GeForce GTX 108... Off | 00000000:B2:00.0 Off | N/A | | 32% 56C P0 57W / 250W | 0MiB / 11178MiB | 2% Default | +-------------------------------+----------------------+----------------------+ +-----------------------------------------------------------------------------+ | Processes: GPU Memory | | GPU PID Type Process name Usage | |=============================================================================| | No running processes found | +-----------------------------------------------------------------------------+
pyrit benchmarkを実行している間も、このアイドル時の画面と正直消費電力があんまり変わらなくて、ごくごくたまにGPUのどれか１つがちょっと電気を使うようになって、また戻る…そんな感じなんですよ。
+-----------------------------------------------------------------------------+ | NVIDIA-SMI 390.30 Driver Version: 390.30 | |-------------------------------+----------------------+----------------------+ | GPU Name Persistence-M| Bus-Id Disp.A | Volatile Uncorr. ECC | | Fan Temp Perf Pwr:Usage/Cap| Memory-Usage | GPU-Util Compute M. | |===============================+======================+======================| | 0 Tesla V100-PCIE... Off | 00000000:3D:00.0 Off | 0 | | N/A 54C P0 48W / 250W | 427MiB / 16160MiB | 0% Default | +-------------------------------+----------------------+----------------------+ | 1 Tesla V100-PCIE... Off | 00000000:3E:00.0 Off | 0 | | N/A 56C P0 51W / 250W | 427MiB / 16160MiB | 0% Default | +-------------------------------+----------------------+----------------------+ | 2 GeForce GTX 108... Off | 00000000:B1:00.0 Off | N/A | | 44% 74C P2 198W / 250W | 167MiB / 11178MiB | 36% Default | ←一時的に使用率が上がった（でもたった36%??） +-------------------------------+----------------------+----------------------+ | 3 GeForce GTX 108... Off | 00000000:B2:00.0 Off | N/A | | 48% 79C P2 85W / 250W | 161MiB / 11178MiB | 0% Default | +-------------------------------+----------------------+----------------------+ +-----------------------------------------------------------------------------+ | Processes: GPU Memory | | GPU PID Type Process name Usage | |=============================================================================| | 0 96620 C /home/psi/src/Pyrit/.env/bin/python 416MiB | | 1 96620 C /home/psi/src/Pyrit/.env/bin/python 416MiB | | 2 96620 C /home/psi/src/Pyrit/.env/bin/python 157MiB | | 3 96620 C /home/psi/src/Pyrit/.env/bin/python 151MiB | +-----------------------------------------------------------------------------+
CPU(htop）もこんな感じで全コア使い切ってない感が否めない…。
でも、それっておかしいですよねぇ？上で読んだように、CPUやGPUごとじゃあなくて、全部に対して仕事を投げまくってるので、理想的な状況としては全GPUと全CPUがTDPギリギリに張り付いてないとおかしいはずなんです。で、せっかく静かにしたファンが全力で回るようになると。ちなみにわたくしリモートで勤務するバーチャルプログラマですので、音のほうは確かめられません。フヒヒ。
というわけで、まずは本当にGPUが遊んでいるのかどうか、プロファイラーで調べられないか試してみます。
PythonとC言語とCUDAが組み合わさった現代のバベルの塔としか言いようがないこの複雑極まりないシステムですが、DeepLearningで非常によくある組み合わせだからかツール自体はかなり整備されておりまして（そしてDeepLearningの場合はさらに統計的機械学習の難しい理論や巨大なデータがその塔の上に積み上がっていく）、こんな感じで非常に簡単にプロファイルできるようになっています：
# nvidia-profilerは別パッケージらしい sudo apt install nvidia-profiler # 測定したいコマンドの前にnvprof -o <出力>.nvvpをつけるだけ。すっごいかんたん！ nvprof -o profile.nvvp pyrit benchmark_long
しかもこのprofile.nvpの結果を見るためのVisual Profilerは、なんとmacでも動きます！リモートのLinuxでももちろん動きます！GPUがあってもなくても！…資本主義ってこえぇなぁ。
nVIDIAのサイトからCUDAのmac版をインストールして、DriverとToolkitとSampleのうち、Toolkitだけインストールします。DriverもインストールできるってことはGeForce積んでるmacもあるんだな…。
で、/Developer/NVIDIA/CUDA-9.2/bin/nvvp （macの場合。CUDAバージョンによって違う）を実行して、openからscpか何かで持ってきたprofile.nvvpを開きます。結果はこんな感じになりましたとさ：
めっちゃスカスカやんけー！
この茶色とか青い棒が出てるところが「計算したで」「CPUとGPUの間でデータのやりとりしたで」を表しているので、このスカスカ具合は、…要するに「GPU全然使えてません」ということになります。つまり、nvidia-smiから雑に考えた仮説は正しかったってこと。
もうすこし拡大して見て行くと、だいたい１秒に一回ぐらいGPUが叩き起こされて、0.06〜0.08秒だけ起こされてまた寝てます。正直ちょっと羨ましい！…いや、そんな頻繁にちょっとだけ起こされるのもやだな。
最初、GPUとCPUの間でパスワードのデータをやりとりするところがボトルネックになるのかなぁ、と予想したりもしていましたが、それは否定されました。計算している80ミリ秒とかに対して、データの転送は0.1ミリ秒程度です。誤差。
ベンチというのは分母と分子が大事なのですよ
仮にほとんどGPUを使っていないとしても、ベンチマークの値の信憑性にただちに影響があるわけではありません。
元のソースコードに戻りましょう：
for i, CD in enumerate(cp.CUDAs):
if CD.compTime > 0:
perf = CD.resCount / CD.compTime
else:
perf = 0
「ベンチマーク」と英語で横文字を使ってみるとなんとなく知的でイケてる感じですが、要するに「仕事率」を測っておるわけです。「やった仕事」を「掛かった時間」で割ってるだけ。
この「掛かった時間」が実際にはどこからどこまでなのかが問題なわけです。
仮に、GPUが1秒間に80ミリ秒しか仕事してないとしても、「掛かった時間」も80ミリ秒なら、その「ベンチマーク」は「GPUの計算の仕事率」を測れていることになります。もし仮にそうなら、GTX1080とTeslaはパスワードクラックという仕事では、そんなに実力に差がないという事になるでしょうね。Pyritに対しては「もっとGPUに仕事割り当ててあげて」と言う事になります。
じゃあ、そうじゃなかったら？…それは、GPUを働かせるために必要な他の仕事の方にばかり時間を取られていて、GPUをうまく動かせていない、という結論が出てきます。例えていうなら、30分の大学院のミーティングに出るために2時間電車乗ってるような。…はぁ…。もし仮にそうなら、ベンチマークの結果はGPUそのものの性能差はあまり反映できていない、という事になるでしょうね。もっといえば、その「余分な仕事」はCPUを使ってるはずなので、このCPUとGPUを同時に走らせるベンチマークは、公平でないことになります。
ソースコードをちょっと書き換えて、この分母であるCD.compTime も表示するようにしましょう。
した結果がこんな感じ：
#1: 'CPU-Core (SSE2/AES)': 528.7 PMKs/s (RTT 2.7) compTime=24 #2: 'CPU-Core (SSE2/AES)': 585.8 PMKs/s (RTT 2.8) compTime=31 #3: 'CPU-Core (SSE2/AES)': 559.6 PMKs/s (RTT 2.9) compTime=35 #4: 'CPU-Core (SSE2/AES)': 537.1 PMKs/s (RTT 2.7) compTime=32 #5: 'CPU-Core (SSE2/AES)': 566.9 PMKs/s (RTT 3.0) compTime=27 #6: 'CPU-Core (SSE2/AES)': 488.4 PMKs/s (RTT 3.0) compTime=33 #7: 'CPU-Core (SSE2/AES)': 569.0 PMKs/s (RTT 3.1) compTime=31 #8: 'CPU-Core (SSE2/AES)': 506.9 PMKs/s (RTT 2.9) compTime=29 #9: 'CPU-Core (SSE2/AES)': 520.3 PMKs/s (RTT 2.8) compTime=19 #10: 'CPU-Core (SSE2/AES)': 579.7 PMKs/s (RTT 2.8) compTime=28 #11: 'CPU-Core (SSE2/AES)': 543.4 PMKs/s (RTT 3.1) compTime=31 #12: 'CPU-Core (SSE2/AES)': 580.9 PMKs/s (RTT 3.0) compTime=33 #13: 'CPU-Core (SSE2/AES)': 569.9 PMKs/s (RTT 2.9) compTime=37 #14: 'CPU-Core (SSE2/AES)': 496.3 PMKs/s (RTT 2.9) compTime=23 #15: 'CPU-Core (SSE2/AES)': 546.1 PMKs/s (RTT 2.8) compTime=34 #16: 'CPU-Core (SSE2/AES)': 564.5 PMKs/s (RTT 2.8) compTime=36 #17: 'CPU-Core (SSE2/AES)': 538.7 PMKs/s (RTT 2.9) compTime=31 #18: 'CPU-Core (SSE2/AES)': 621.0 PMKs/s (RTT 2.8) compTime=25 #19: 'CPU-Core (SSE2/AES)': 527.8 PMKs/s (RTT 2.8) compTime=31 #20: 'CPU-Core (SSE2/AES)': 492.7 PMKs/s (RTT 2.8) compTime=34 #21: 'CPU-Core (SSE2/AES)': 532.0 PMKs/s (RTT 2.8) compTime=28 #22: 'CPU-Core (SSE2/AES)': 558.4 PMKs/s (RTT 2.9) compTime=29 #23: 'CPU-Core (SSE2/AES)': 548.8 PMKs/s (RTT 2.8) compTime=31 #24: 'CPU-Core (SSE2/AES)': 528.6 PMKs/s (RTT 2.9) compTime=32 #25: 'CPU-Core (SSE2/AES)': 594.7 PMKs/s (RTT 2.8) compTime=28 #26: 'CPU-Core (SSE2/AES)': 508.1 PMKs/s (RTT 2.8) compTime=33 #27: 'CPU-Core (SSE2/AES)': 534.2 PMKs/s (RTT 2.9) compTime=32 #28: 'CPU-Core (SSE2/AES)': 545.9 PMKs/s (RTT 3.1) compTime=31 #29: 'CPU-Core (SSE2/AES)': 543.0 PMKs/s (RTT 3.0) compTime=39 #30: 'CPU-Core (SSE2/AES)': 550.1 PMKs/s (RTT 2.6) compTime=29 #31: 'CPU-Core (SSE2/AES)': 595.8 PMKs/s (RTT 3.1) compTime=31 #32: 'CPU-Core (SSE2/AES)': 581.9 PMKs/s (RTT 2.7) compTime=30 #33: 'CPU-Core (SSE2/AES)': 537.9 PMKs/s (RTT 2.9) compTime=29 #34: 'CPU-Core (SSE2/AES)': 566.2 PMKs/s (RTT 3.0) compTime=30 #35: 'CPU-Core (SSE2/AES)': 563.1 PMKs/s (RTT 2.6) compTime=24 #36: 'CPU-Core (SSE2/AES)': 590.0 PMKs/s (RTT 2.7) compTime=32 #37: 'CPU-Core (SSE2/AES)': 581.8 PMKs/s (RTT 2.7) compTime=27 #38: 'CPU-Core (SSE2/AES)': 566.3 PMKs/s (RTT 2.7) compTime=33 #39: 'CPU-Core (SSE2/AES)': 516.1 PMKs/s (RTT 3.2) compTime=28 #40: 'CPU-Core (SSE2/AES)': 561.8 PMKs/s (RTT 2.9) compTime=35 #41: 'CPU-Core (SSE2/AES)': 542.7 PMKs/s (RTT 2.9) compTime=29 #42: 'CPU-Core (SSE2/AES)': 577.9 PMKs/s (RTT 2.9) compTime=29 #43: 'CPU-Core (SSE2/AES)': 586.3 PMKs/s (RTT 3.0) compTime=33 #44: 'CPU-Core (SSE2/AES)': 523.4 PMKs/s (RTT 3.0) compTime=30 #45: 'CPU-Core (SSE2/AES)': 526.7 PMKs/s (RTT 2.9) compTime=32 #46: 'CPU-Core (SSE2/AES)': 505.5 PMKs/s (RTT 2.9) compTime=32 #47: 'CPU-Core (SSE2/AES)': 567.8 PMKs/s (RTT 2.7) compTime=24 #48: 'CPU-Core (SSE2/AES)': 521.5 PMKs/s (RTT 2.9) compTime=32 CUDA: #1: 'CUDA-Device #1 'Tesla V100-PCIE-16GB'': 113061.9 PMKs/s (RTT 0.4) compTime=11.3 #2: 'CUDA-Device #2 'Tesla V100-PCIE-16GB'': 120956.8 PMKs/s (RTT 0.4) compTime=13.1 #3: 'CUDA-Device #3 'GeForce GTX 1080 Ti'': 94154.2 PMKs/s (RTT 0.4) compTime=13.3 #4: 'CUDA-Device #4 'GeForce GTX 1080 Ti'': 96664.7 PMKs/s (RTT 0.5) compTime=16.4
45秒のベンチに対して、10秒程度。たしかにCPUに比べてかなり短いですが、1秒中80ミリ秒、つまり8%しか使ってないことを考えるとあまりに長いです。Pyritくんが口ではGPUで実行している！といいつつ、実はそうでない部分がかなり占めていて、GPUを全然使い切れていない可能性はやはりかなり高い、と考えてよいでしょう。
もう一つ。CPUもGPUも、どっちも45秒のベンチマークのうち、けっこうの部分遊んでいます。htopであんまりコアを使い切ってない気がしたのもここで説明がつきました。これはどう解釈すればいいのかといえば…たぶん、ダミーのパスワードの生成が、追いついてないんじゃないでしょうか。CPUやGPUがすぐパスワードを処理して「もっとくれや！」って言うけれど、
["barbarbar%s" % random.random() for i in xrange(bsize)]としてパスワードをどんどん作る処理が追いついてない。
月刊Pyrit、今月のまとめなのですよ
- benchmarkはパスワードクラックの一部の処理しか測ってない
- GPUもCPUも遊びまくっている
- nVIDIAのプロファイラきれい（明らかにEclipse製）
さぁて、来月の月刊Pyritは何なのですよ？
いきあたりばったりで書いてるのでどうなるかはわかんないんですけど、このボトルネックたちと遊んでいきましょう。いいっすね、なんかやっと技術ブログっぽくなってきた。…台風の低気圧で今日はテンションがひくいのですよ。みなさまも強い風に飛ばされないように気をつけて〜。
そう言えば先月書いた正解のパスワード、検閲されちゃいましたね。「xxxxxxxxxxx」ですって、いったいどんな文字列だったんでしょう、前後の文脈から想像をかき立てられちゃいますねぇ。「えっちなことば」って昔こんな感じで生まれたのかな。フヒヒ。
