サーバー技術

GPUを使って無線LANをクラックする話 / プロファイラの言うことがみんな違うよ編

linkucojp

ついにソメイヨシノも咲いて、「春」って感じですな。

梅も桜も花の形が似ていますが、それもそのはず。桜も梅も、どちらもバラ科サクラ属なのだそうです。じゃ、他には？という事で調べてみたのですが、モモもそうなんだって。そういえばたしかに、さくらんぼと桃の実ってなんとなく似てますね。

というわけで（？）、今回はモモの花です。

前回までのまとめ

前回までこの「GPUを使って無線LANをクラックする話」では、Pythonの標準プロファイラcProfileを使って測定して議論していましたが、cProfileは実は普通に使う限りではメインスレッドしか測定してくれない事がわかりました（別記事）。マルチスレッドで動いているPythonプログラムのためのプロファイラはいろいろあるけれど（別記事）、C言語のスタックまでプロファイルしてくれる、vmprofというのがどうやら我らがPyritには良さそうです。というわけで、このvmprofを使って再度取り直します。

vmprofを使ってもう一回測定するぜ！→やっぱなんか変だぜ！

というわけでモクモクと測定していきます。

まず可視化のためのサーバを建てる必要があります（デフォルトだとvmprof.comを使うようになっているのですが、このサーバは落ちたまま放置されているようです）。

git clone https://github.com/vmprof/vmprof-server.git
cd vmprof-server

pip install -r requirements/development.txt
python manage.py migrate
python manage.py runserver -v 3

vmprof自体はpipで入るのでもっと簡単です。ただし、さっき自分が建てたWebサーバを指定するのを忘れずに：

pip install vmprof
python -m vmprof --web --web-url "http://127.0.0.1:8000/" pyrit benchmark

で、CPUを１コアだけ使って解くようにした結果がこちら：

全処理時間のうちrun関数が95%使っていて、さらにCPUDevice_solveというC言語の関数が2.5%使っている、などなど。

95%を使っているというrun関数はパスワードを処理するスレッドのエントリーポイントです。CPU/CUDA/OpenCLで共通で、キューから候補のパスワードを取り出し(_gather)、self.solve()を使って計算して別のキューへ投げる(_scatter)という簡単なものです：

    def run(self):
        while not self.shallStop:
            essid, pwlist = self.queue._gather(self.buffersize, timeout=0.5)
            if essid is not None:
                if not self.isTested:
                    self._testComputeFunction(101)
                    self.isTested = True
                t = time.time()
                res = self.solve(essid, pwlist)  # ←ここのメソッド呼び出しでCPU/CUDA/OpenCLが分岐する
                assert len(res) == len(pwlist)
                self.compTime += time.time() - t
                self.resCount += len(res)
                self.callCount += 1
                if self.compTime > 0:
                    # carefully move towards three seconds of execution-time
                    avg = (2 * self.buffersize +
                           (self.resCount / self.compTime * 3)) / 3
                    self.buffersize = int(max(self.minBufferSize,
                                              min(self.maxBufferSize, avg)))
                self.queue._scatter(essid, pwlist, res)

この関数と、そこから先の処理が95%を占めている、というのは理解できます。この「95%」というのは、SIGPROFの基準で95%なので、全スレッドで実際に実行された時間のうち、95%の時間という意味になるようです。言い換えると、sleepしたりしている時間は入らないということです。

しかし、CPUDevice_solveが2.5%とはどういう事か。CPUDevice_solveは、CPUのコアで実行したときに実際にOpenSSLを使ってSHA1を何度も計算する処理です。一番重い、CPUを酷使する処理のはずで、流石にたった2.5%という事はありえないはずです。

…バグかなぁ？

cProfile、ふたたび

cProfileはpython -m cProfile pyrit benchmark と実行するとメインスレッドしかプロファイルしてくれませんが、ソースコードを書き換えれば別のスレッドのプロファイルも取ることができます。これで同じ処理を測定してみます。

さきほどのrun関数の周囲を次のようなコードで囲みます：

    def run(self):
        import cProfile
        prof = cProfile.Profile()
        prof.enable()
        try:
            # ... 元々の処理 ...
        finally:
            prof.disable()
            prof.dump_stats('{}.dat'.format(threading.currentThread().ident))

threading.currentThread().ident はスレッドごとに異なる値で、これをファイル名に使っています。

次のようなコマンドで測定結果を確認してみると（pstatsのドキュメントはこちら）：

$ python
Python 2.7.15rc1 (default, Nov 12 2018, 14:31:15) 
[GCC 7.3.0] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import pstats
>>> s = pstats.Stats('140487566550784.dat') # ←ファイル名は毎回異なる
>>> s.sort_stats('cumtime').print_stats()
Fri Mar 29 11:59:24 2019    140487566550784.dat

         3194 function calls in 69.366 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       28   68.735    2.455   68.735    2.455 {method 'solve' of '_cpyrit_cpu.CPUDevice' objects}
       28    0.004    0.000    0.627    0.022 /home/server01/src/Pyrit/cpyrit/cpyrit.py:637(_gather)
       10    0.001    0.000    0.622    0.062 /usr/lib/python2.7/threading.py:309(wait)
       54    0.620    0.011    0.620    0.011 {time.sleep}
        1    0.000    0.000    0.116    0.116 /home/server01/src/Pyrit/cpyrit/cpyrit.py:99(_testComputeFunction)
       27    0.003    0.000    0.004    0.000 /home/server01/src/Pyrit/cpyrit/cpyrit.py:692(_scatter)
      216    0.001    0.000    0.001    0.000 {method 'extend' of 'list' objects}
       55    0.000    0.000    0.000    0.000 /usr/lib/python2.7/threading.py:285(__enter__)
       54    0.000    0.000    0.000    0.000 /usr/lib/python2.7/threading.py:400(notifyAll)
       54    0.000    0.000    0.000    0.000 {sorted}
      139    0.000    0.000    0.000    0.000 {method 'acquire' of 'thread.lock' objects}
... (以下省略） ...

run関数の内側でprof.enable()としているので、上の結果の一覧にrun関数は出てきません。run関数以下の内訳を測定している、ということになります。処理に掛かった全時間が69.366秒、結果の１行目によるとCPUDeviceのsolveメソッドの実行に掛かった時間が68.735秒（約99%）、などなどといったことが分かります。

CPUDeviceのsolveメソッドの実態は、vmprofでCPUDevice_solveとなっていたC言語の関数です。vmprofでは処理の2.5%を占めているというこの関数が、cProfileによるとほぼ99%だそうで…えー、言ってることが、真逆ですねぇ。

まとめ

SIGPROF（アラーム・シグナル）を使った統計的プロファイラであるvmprofを使ってPyritのbenchmarkを測定してみたものの、標準の決定論的プロファイラであるcProfileとは大きく結果が異なる事がわかりました。状況証拠から言って、vmprofのバグじゃないかなぁと思います（しかし残念ながらもう開発も止まってしまった模様…）。前回のような簡単なコードでは結果が一致したからといって信用せず、常に複数のプロファイラを併用して結果を突き合わせたほうが良いのかもしれません。

…マジ、みんなどうやってプロファイル取ってるんだ？と思って調べたらTensorFlowは自分たち専用のプロファイラを作ってた。まっ、そうですよねー。

残念ながら大人の事情により、今回で一端このシリーズは最終回らしいです。機材を貸してくれた人ありがとう。…ちょっとぐらい速くしたかったなぁ。