DCGANでテキスト生成を試してみた2

こんにちは、Link-Uの町屋敷です。

前回は、Word2Vec(以下W2V)とDCGANで英語のテキストを生成しているサイトがあったので、日本語でも試しよう!と言う事で実装してみたところなかなか残念な結果だったので、今回はもう少しなんとかならないか続きをします。

生成結果を視覚化する

結果を良くするにはパラメーター調整をしていかなければならないんですが、画像と違って文章生成の場合生成された結果が直感でわかりにくくなっています。

そこで、わかりやすくするためにジェネレーターが生成した結果をWord2Vecで文章に戻すのではなく、それを次元圧縮してプロットします。

    def show_tsne(self, epoch, real, fake, save_pic):
        from sklearn.manifold import TSNE
        col = np.zeros(len(real))
        col = np.append(col, np.ones(len(fake)))
        
        comp = TSNE(n_components=2, random_state=0).fit_transform(np.reshape(np.vstack((real,fake)), (-1, self.img_cols * self.img_rows * self.channels)))
        plt.scatter(comp[:, 0], comp[:, 1], c=col)
        plt.xlim(-30,30)
        plt.ylim(-30,30)
        if save_pic:
            plt.savefig("images/sent_gan_%d.png" % epoch)
        else:
            plt.show()
        plt.close()

本物の文章と偽物の文章を受け取ってTSNEで圧縮してプロット。今回は本物を紫、偽物を黄色でプロットする

いい偽物の文章が生成されていれば、2色のプロットは混ざり合うが、そうでなければ分離される。

ためしに前回の最終結果で試してみるとこんな感じ。

Epoch 100

Epoch 1000

完全に分離されているのがわかります。

MeCabからの品詞の情報を使う

上記の確認方法を使ってDやGのモデル、W2Vのベクトルの長さ、学習率などのパラメーターをいろいろいじくり回しましたが良い結果にはなりませんでした。

出力された結果を見てみると、品詞がガバガバになっていたので、MeCabから品詞の情報を抜き出して、W2Vの後ろに追加したら多少マシになるんじゃないたと思って追加しました。

    def AnalyzeWord(self, word):
        gen = self.mecab.parse(word, as_nodes=True)
        for w in gen:
            return w.posid, w.surface

品詞はposidから取得できます。posidさえあれば単語の活用は単語の原型から変形させればいいので、簡単のために入力する単語をすべて原型にしました。

結果はこんな感じ。

Epoch 100

Epoch 1000

多少マシなはなったがまだひどい。

ちなみに生成された文章はこんな感じ。

掘り起こしぎゅれんずつ欄オアフまた。。

掘り起こしぎゅれんずつプロバスケットボールリーグオアフまた。。

掘り起こしぎゅれんずつシティーハンタースペシャルオアフまた。。

最後には。がつくっていうのくらいしか学習できてない感がある。

品詞の並びを生成してそれを単語に変換する

品詞の並びを生成する

流石にこのままでは終われないので作戦変更(妥協)。

直接雑音から文章を生成するのを諦め、DCGANと2つ使った文章の生成を目指す。

1つめのDCGANで雑音から品詞の列を生成するジェネレーターを生成し、

品詞を単語に変換するニューラルネットを2つめのDCGANで生成することを目指す。

まず雑音から品詞の列を生成する。これが出来ないなら話にならない。

今までW2Vを入力していたところの先程の品詞の列のみを入力してDCGAN。

Epoch 100

Epoch 300

Epoch 500

Epoch 1000

Epoch 5000

どうやら品詞の列ぐらいは生成できるようだ。

学習した重みを保存する。転移学習に使えるよう各レイヤーに名前わつけて、(name = ‘PC1’など)combinedではなけgenerateorの重みを保存する。

品詞の列を生成するニューラルネットをpos_makerと名付ける

    def build_pos_maker(self):
        model = Sequential()
    
        model.add(Dense(256 * int(self.img_rows * self.img_cols), activation="relu",
                          input_dim=self.latent_dim, name = 'PD1'))
        model.add(Reshape((self.img_cols , self.img_rows, 256)))
        model.add(UpSampling2D())
        model.add(Conv2D(128, kernel_size=3, strides=2, padding="same", name = 'PC1'))
        model.add(BatchNormalization(momentum=0.8, name = 'PB1'))
        model.add(Activation("relu"))
        model.add(UpSampling2D())
        model.add(Conv2D(128, kernel_size=3, strides=2, padding="same", name = 'PC2'))
        model.add(BatchNormalization(momentum=0.8, name = 'PB2'))
        model.add(Activation("relu"))
        model.add(UpSampling2D())
        model.add(Conv2D(64, kernel_size=3, strides=2, padding="same", name = 'PC3'))
        model.add(BatchNormalization(momentum=0.8, name = 'PB3'))
        model.add(Activation("relu"))
        model.add(UpSampling2D())
        model.add(Conv2D(32, kernel_size=3, strides=2, padding="same", name = 'PC4'))
        model.add(BatchNormalization(momentum=0.8, name = 'PB4'))
        model.add(Activation("relu"))
        model.add(Conv2D(1, kernel_size=3, strides=1, padding="same", name = 'PC5'))
        model.add(Activation("tanh"))
    
        model.summary()
        
        noise = Input(shape=(self.latent_dim,))
        print(noise)
        pos = model(noise)
    
        return Model(noise, Container(noise, pos)(noise), name='pos_gen')

//略

        self.generator.save_weights('pos_gan_weight.h5')

2つの学習機をつなげる

        # The generator takes noise as input and generates imgs
        z = Input(shape=(self.latent_dim,))
        pos = self.pos_maker(z)
        img = Input(shape=self.txt_shape)
        
        fake = self.generator(pos)
        # For the combined model we will only train the generator
        #Fix pos_maker weights
        self.pos_maker.load_weights('pos_gan_weight.h5', True)
        self.pos_maker.trainable = False

z(雑音)をpos_makerで品詞の列に変換して、generatorで単語にする。pos_makerの重みは更新しない。

2つめの学習機を初期化する

入力に品詞出力に単語のW2V列をセットして学習するこれを初期値とする。

    def train_pos_to_word(self):
        pos_to_w2v = self.generator
        pos_to_w2v.compile(loss='mse',
        optimizer='adam')
        X_train = joblib.load('{0}/pos_labels.pkl'.format(WRITE_JOBLIB_DIR))
        X_train = np.reshape(X_train, (-1,self.img_cols, self.img_rows, 1))
        X_test = joblib.load('{0}/vectorized_words.pkl'.format(WRITE_JOBLIB_DIR))
        X_test = np.reshape(X_test, (-1, self.img_cols, self.img_rows , self.channels))
        pos_to_w2v.fit(X_train, X_test, batch_size=32,
            epochs=12,
            verbose=1)

結果

かかった時間は手元のパソコンとGPUサーバーで2倍ほどの差があった。

Epoch5

Epoch40

Epoch400

長く学習するとモードがなくなって悪化する。このほうほうではすく偏るらしく元のサイトでも課題になっていた。

Epoch40のときの生成分がこちら。

収録オニヅカ原典する通りは単体。

がけっぷち相当し初めてリリース。。。

詳細は記述実際は彼奴。。

すべてリリース必ずた。。。。

巻が第発売全リリース。。

は本来の年リリース。。。

はエピローグ相当する両性それぞれ取消。

が」全巻。。。。

巻から日発売。。。。

スケリグカン・シヌ。。。。。。

第初めてリリースは取消。。。

ミッションイー。。。。。。。

元データが会話文ではないので名詞が多い。

またこの手のやつは大体そうだが、別に意味を理解しているわけではないので、意味不明な文も結構生成されている。

まとめ

DCGANで文章生成は品詞の列は作れることはわかった。

ただ文章生成になると微妙なので、別の手法(別のGANとかRNN系)も試してみて比較したほうが良さそう。

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

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

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

というわけで(?)、今回はモモの花です。

前回までのまとめ

前回までこの「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を1コアだけ使って解くようにした結果がこちら:

全処理時間のうち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秒、結果の1行目によるとCPUDeviceのsolveメソッドの実行に掛かった時間が68.735秒(約99%)、などなどといったことが分かります。

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

まとめ

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

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

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

マルチスレッドで走るPythonプログラムをプロファイルするには?

さて、前の記事では実験とソースコード読解の両方から、python -m cProfile test.pyとして測定した場合、メインスレッドで実行される部分しか計測されていない事がわかりました。

でも、「Deep LearningといえばPython」な昨今、マルチスレッドで動くPythonのプログラムは目の前にいっぱい存在するわけで、それらを測りたいわけで。どげんかせんといかん。

ある意味で本題はここからです。方法をいくつか調べました。

その1:起動したスレッドごとにcProfileを設定する

cProfile.Profileクラスを使うと、python -m cProfile test.pyのようにしてコマンドライン引数を使って行っていたプロファイリングを、コード中からもできます。この方法ならメインスレッド以外にもプロファイラを設定して計測することができます。

こんな感じ:

import threading
import cProfile
import math


class Worker(threading.Thread):
    def __init__(self, n: int):
        threading.Thread.__init__(self)
        self.n = n
        self.sum = 0

    def run(self):
        prof = cProfile.Profile() # プロファイラの作成
        prof.enable() # プロファイラの有効化
        try:
            for i in range(0, self.n):
                self.sum += math.sin(i * i)
        finally:
            prof.disable() # プロファイラを止める
            prof.print_stats('cumtime') # 結果の表示


def main():
    th = Worker(100000000)
    th.start()
    th.join()


if __name__ == '__main__':
    main()

前回と違い、今度こそはmath.sinが出てきます:

% python3 test.py
         100000001 function calls in 18.187 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
100000000   18.187    0.000   18.187    0.000 {built-in method math.sin}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

しかしながら、この方法はソースコードを書き換えなければなりません。多くの場合において不可能ではないでしょうが、若干居心地は悪いですし、run関数がC言語で書かれていたりすると、正直かなり大変です。

とはいえ、この方法では確実に枯れているであろう、そしてPython開発チームが公式にメンテナンスしている、cProfileを使うことができます。cProfileに慣れているとか、なんかgithubに上がってる新しいよくわかんないプロダクトは嫌だなぁ、といった人にはこれが良いかもしれません。

その2:vmprof

前回読んだように、cProfileは全ての関数呼び出し(とreturn)を追跡して記録しているのですが、こういうプロファイラを「決定論的プロファイラ」と呼ぶそうです。わざわざそんな名前がつくからには別の種類のプロファイラもあるわけで、vmprof統計的プロファイラです。

具体的に何をどう測るのかというと、(Linuxも含めたUNIXでは)setitimerというOSの提供するインターバル・タイマーを使って、定期的にスレッドを全て止め、libunwindを使ってスタック上のコール・チェーンの状態(今、どの関数がどの関数を呼び出している最中なのか)を記録し、その情報を使って「測定」しているようです。

なので、cProfileと違ってすべての関数呼び出しが把握できるわけではなく、例えば短時間だけ実行されるあまり呼ばれない関数は取りこぼされることがあります。まぁ、そういう関数はプロファイルを取って突き止めたい「ホットな」関数ではないですから、測定できなくてもよい、という判断なのでしょう。

一方で、cProfileはC言語の関数に関しては前回見た通りPythonのインタプリタから呼び出す瞬間に測定していて、そこから先のC言語間の関数呼び出しは関知しない(できない)わけですが、この方法ではC言語の部分まで一緒にプロファイリングできちゃいます。CUDAやC言語の複雑に絡み合うシステムには、こっちの方が有用かもしれません。

結果のビジュアライズも中々わかりやすい。C言語の関数も、シンボル情報がある部分に関しては関数名も表示されます:

run関数でmath.sinの和を計算している処理のうち、integerをdoubleにするPyFloat_AsDoubleがどうやら11%程度使っているらしい、といった情報までわかります。

難点があるとすれば、測定するスレッドが決められない点でしょうか。ソースコードを追いかけた限りでは、必ず全てのスレッドを追いかけて結果を合算しているように読めました。同じクラスから派生するさまざまなクラスが一緒に走る場合(今回高速化しているPyritがまさにそのケースに当てはまる)、ちょっとデータの解釈に困るかもしれません。

C言語のスタックまで計測出来る点は素晴らしいのですが、普通に実行しただけでは必ずしも関数名が見えるとは限らない点はちょっと残念です。python3-dbgパッケージを入れてデバッグ用pythonでも実行してみたのですが、内部の全ての関数シンボルまでは残っていないようでした。VMの中身を深く掘らないといけない時は、pythonを自分でビルドする必要があるでしょう。

このWebインターフェイスなのですが、デフォルトではvmprof.comというウェブサービスにプロファイルした結果をアップロードして表示する(!)というクラウド絶頂期のイマドキらしい中々大胆な作りになっていまして、会社で書いてるプロプライエタリなソースで利用するのにはちょっと憚られるかもしれません。まぁもっとも、ここ最近はずっと落ちているのでそもそもアップロード出来ないんですが(それはそれでどうなんだ)。

もちろん、サーバのソースコードも公開はされていて比較的簡単には使えるので、自分で立てればそのへんは解決可能(というかそうしないと使えない)です。

その3:Pyflame

上のvmprofと同じ統計的プロファイラですが、こちらはLinuxでデバッガを実装するときに使われるシステムコールであるptraceを使っているらしいです(よってLinux専用)。ptraceを使っているおかげで、すでに動いているプロセスに対してアタッチ出来るのが強みだそうな。

Python3.7には未対応な上でIssueには進捗がなく、Python2.7で試してみた限り、Cのスタックも追いかけてくれませんでした(ptraceの力をもってすれば原理的には可能だと思うんですが…)。2019年3月現在は、あんまりおすすめできない選択肢だと思います。

その4:pprofile

こちらは決定論的プロファイラと統計的プロファイラの両方の実装が含まれています。ドキュメントに書いてあるとおり、決定論的・統計的プロファイラをのどちらでもマルチスレッドに対応していて、しかもPythonだけで書かれています。どうなっているのか調べてみたところ、threading.settraceというsys.settraceのマルチスレッド対応版みたいなAPIがあって、それをそのまま利用しているようです。

全てがPythonで書かれている都合上オーバーヘッドが少々大きいのと、C言語のプロファイルは取れません。ただ、著者の主張している通り、動かすのはすごく楽です。測定対象のソースコードを書き換える必要性も一切ありません。

その他:マルチスレッドは(そのままでは)ダメだったやつ

DISるつもりは無いんですが、マルチスレッドはダメそうだったやつも記録しておきます。シングルスレッドのPythonプログラムをデバッグしているときは便利なんじゃないでしょうか。

cprofilev

cProfileの便利なラッパー、だそうな。しかしソースを読んだ限り、便利になった代償として、マルチスレッドでこれを使うのはさらに難しくなっているようです。

line_profiler

cProfileと違って1行ごとに測定できる、というのが売りの決定論的プロファイラ。仕組みもcProfileとだいたい同じで、違いはPyEval_SetProfileの代わりにPyEval_SetTrace使っていること。この関数を使うとPythonの関数の呼び出しの記録だけでなく、Pythonの命令が1行実行されるごとにcallbackが呼ばれるそうな(逆に、C言語の関数のCALL/RETURNは記録されない)。

ここ以外の事情も概ねcProfileと同じ感じでして、コードを修正しなくてもプロファイルを取ってくれるというkernprofコマンドのmain関数はメインスレッドしか測らないものの、手動で測定コードを挿入すればマルチスレッドでも測れるようになっているように読めます(段々めんどくさくなってきて実験はしてません)。

まとめ

プロファイラもまさに十人十色といった感じでした。プロファイラを使う前に、時間を掛けてソースコード読んで、何をどう測っているのか、調べる価値はあると思います。

どれが良いのかは、正直なところ、測定対象のプログラムによると思います。

  • とりあえず動かしたいだけならpprofが一番楽です。
  • pyflameはおすすめできないと書きましたが、今すでに動いているPythonのプログラムをプロファイルできるのはpyflameだけです。
  • Cのコールスタックまでプロファイルを取れるのは、vmprofだけです。
  • cProfileは公式でメンテナンスされていて、枯れているでしょう。

今回ターゲットにしている、CとCUDAとPythonのアマルガムであるPyritの場合は、vmprofが適切かなぁと思います。CaffeやTensorFlowの人たちは何使ってプロファイル取ってるんだろう…。

Pythonの標準プロファイラ、cProfileの中身を追いかける

Python、使ってますか。

わたしは最近、諸事情により、最近PythonとC言語とCUDAを使ったソフトウェア高速化に取り組んでいます(できているとは言っていない)。ちなみに、ディープラーニングじゃないよ。

高速化するときに最も重要な道具は、ベンチマークとプロファイラであることを疑う人は居ないと思います。ベンチマークで高速化の効果を測定し、プロファイラでボトルネックを発見する。これが基本的かつ王道のサイクルですよね。

ところで、プロファイラはどのような仕組みで動いているのでしょうか。追いかけたこと、あります?

何を測っているのか知らずにプロファイラを使う者がおるか!

プロファイラは何を測っていて、何を測っていないのか。

Pythonに最初からついてくるプロファイラ「cProfile」を使ってプロファイリングを行っていたのですが(CUDAとC以前にPythonがボトルネックっぽいので)、わたしはてっきりこのプロファイラはGILを握っている全てのスレッドのそれぞれの動作を測ってるんだと思ってました。だって、「マルチスレッドだけどGILのせいで同時に動くスレッドは1つしかない」というPythonのプログラムの動作をプロファイリングする方法としては、それが一番妥当かつ自然に感じられたからです (でも、今考え直してみると、そうでもない気がしてきた…わからん)。ドキュメントにはマルチスレッドに関しては何にも書いてないし。

しかし、Profilerの出力する結果を見ているとどうにもおかしい気がしてきまして。おおむね予想通りの結果も出てくるけど、どこかおかしい気もする。わたしの予想の方が間違っているのか、プロファイラの測定の誤差や限界なのか。うーん。

なんでそんな考えが浮かんでくるのかといえば、(今回のも含めて)高速化したいプログラムというのは大抵複雑だからです。

というわけで、超単純なサンプルで測ってみました:

import threading
import cProfile
import math

class Worker(threading.Thread):
    def __init__(self, n: int):
        threading.Thread.__init__(self)
        self.n = n
        self.sum = 0

    def run(self):
        for i in range(0, self.n):
            self.sum += math.sin(i * i)

def main():
    th = Worker(100000)
    th.start()
    th.join()

if __name__ == '__main__':
    main()

見たまんまですが、math.sin(i * i)の和を計算するという何の意味もない計算を、メインスレッドとは別のスレッドで行う、無意味だけど時間の掛かるプログラムです。

これをcProfileして出た結果は:

% python -m cProfile -s 'cumtime' test.py
         45 function calls in 21.670 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   21.670   21.670 {built-in method builtins.exec}
        1    0.000    0.000   21.670   21.670 <string>:1(<module>)
        1    0.000    0.000   21.670   21.670 test.py:17(main)
        5   21.670    4.334   21.670    4.334 {method 'acquire' of '_thread.lock' objects}
        1    0.000    0.000   21.665   21.665 threading.py:1024(join)
        1    0.000    0.000   21.665   21.665 threading.py:1062(_wait_for_tstate_lock)
        1    0.000    0.000    0.005    0.005 threading.py:828(start)
        1    0.000    0.000    0.005    0.005 threading.py:533(wait)
        1    0.000    0.000    0.005    0.005 threading.py:263(wait)
        1    0.000    0.000    0.000    0.000 {built-in method _thread.start_new_thread}
...(略)...

無意味な計算のために20秒ほど掛かっていていますが、その計算に関わっているWorker.run関数やmath.sinは一切リストアップされておらず、スレッドのjoinのみが入っています。

…えー。つまり、cProfileはマルチスレッド対応してないんだねぇ。

…今まで計測した結果、全部無駄だねぇ。…まぁ、そういう事もあるよ。

ソースコードを追いかける

せっかくですから、この機会にソースコードを追いかけて、どのようにプロファイルをしているのか、その仕組みを掴んでおくことにします。事前に予告しておきますが、本当に眺めて見学するだけです。さらに深くソースコードを追いかけたい時のとっかかりにでも使ってください。とはいえ、プロファイラの中身について言及している記事はインターネッツ上にあんまりないので、今回このように記事を書いております。

マルチスレッドのプログラムを手っ取り早くプロファイルしたい人は、読み飛ばして次の「マルチスレッドで走るPythonプログラムをプロファイルするには?」へ進むのも良いかもしれません。

さて。コンソールからpython -m cProfile test.pyを実行すると、cProfile.Profilerの次の関数が最終的には呼ばれます:

# https://github.com/python/cpython/blob/fcd5e84a515e19409840c570730f0728e9fcfc83/Lib/cProfile.py#L97

    def runctx(self, cmd, globals, locals):
        self.enable()
        try:
            exec(cmd, globals, locals) # コマンドライン引数で指定されたファイルの中の文字列を実行する
        finally:
            self.disable()
        return self

exec関数はいわゆるeval関数の親戚で、与えられた文字列(cmd)を、所定の環境の下で実行する組み込み関数です。となると、その周囲を囲うenable/disableが重要そうです。

self.enableの実態を追いかけていくとC言語の関数に行き着きまして:

// https://github.com/python/cpython/blob/62be74290aca26d16f3f55ece7ff6dad14e60e8d/Modules/_lsprof.c#L683

static PyObject*
profiler_enable(ProfilerObject *self, PyObject *args, PyObject *kwds)
{
    int subcalls = -1;
    int builtins = -1;
    static char *kwlist[] = {"subcalls", "builtins", 0};
    if (!PyArg_ParseTupleAndKeywords(args, kwds, "|ii:enable",
                                     kwlist, &subcalls, &builtins))
        return NULL;
    if (setSubcalls(self, subcalls) < 0 || setBuiltins(self, builtins) < 0)
        return NULL;
    PyEval_SetProfile(profiler_callback, (PyObject*)self);
    self->flags |= POF_ENABLED;
    Py_RETURN_NONE;
}

いちばん重要なのは、PyEval_SetProfileの呼び出しだと思います。これはpythonインタプリタの提供するプロファイルのための関数を設定する関数で、cProfileはこの言語処理系の機能をそのまま使っています。ちょっと面白いのは、この関数は外部に公開された、つまり(中の人でなくても)誰でも使えるC言語の関数なことで、やろうと思えば誰でも「ぼくのかんがえたさいきょうのプロファイラ」が作れるということになります。

さて、そのPyEval_SetProfileのソースも見てみましょう:

// https://github.com/python/cpython/blob/8479a3426eb7d1840473f7788e639954363ed37e/Python/ceval.c#L4371

void
PyEval_SetProfile(Py_tracefunc func, PyObject *arg)
{
    PyThreadState *tstate = _PyThreadState_GET();
    PyObject *temp = tstate->c_profileobj;
    Py_XINCREF(arg);
    tstate->c_profilefunc = NULL;
    tstate->c_profileobj = NULL;
    /* Must make sure that tracing is not ignored if 'temp' is freed */
    tstate->use_tracing = tstate->c_tracefunc != NULL;
    Py_XDECREF(temp);
    tstate->c_profilefunc = func;
    tstate->c_profileobj = arg;
    /* Flag that tracing or profiling is turned on */
    tstate->use_tracing = (func != NULL) || (tstate->c_tracefunc != NULL);
}

一行目のPyThreadState_GETはスレッドごとに違うPyThreadStateオブジェクトを返す関数(参考:スレッド局所記憶)です。なので、プロファイラの関数はスレッドごとに設定されます。というわけで、python -m cProfile test.pyで測定した時は、メインスレッド以外の別のスレッドに関してはやっぱり一切計測しません

tstate->c_profilefuncに設定される関数は、C言語とPythonの関数のCALL/RETURNの時に呼ばれるようになっていまして、cProfileでプロファイルを取る時の関数もその情報を使って集計しているのがわかります。

実際にこの関数が呼ばれているところも追いかけておきましょう。

PythonからPythonの関数の呼び出し

Pyrhonの関数のCALL/RETURNに関しては、関数の本体(のバイトコード)を実行する_PyEval_EvalFrameDefaultというインタプリタの核心部みたいな関数の最初と最後で呼ばれます:

# https://github.com/python/cpython/blob/842a2f07f2f08a935ef470bfdaeef40f87490cfc/Python/ceval.c#L940

        if (tstate->c_profilefunc != NULL) {
            /* Similar for c_profilefunc, except it needn't
               return itself and isn't called for "line" events */
            if (call_trace_protected(tstate->c_profilefunc,
                                     tstate->c_profileobj,
                                     tstate, f, PyTrace_CALL, Py_None)) {
                /* Profile function raised an error */
                goto exit_eval_frame;
            }
        }
    }

# https://github.com/python/cpython/blob/842a2f07f2f08a935ef470bfdaeef40f87490cfc/Python/ceval.c#L3575

return_or_yield:
    if (tstate->use_tracing) {
        if (tstate->c_tracefunc) {
            if (call_trace_protected(tstate->c_tracefunc, tstate->c_traceobj,
                                     tstate, f, PyTrace_RETURN, retval)) {
                Py_CLEAR(retval);
            }
        }
        if (tstate->c_profilefunc) {
            if (call_trace_protected(tstate->c_profilefunc, tstate->c_profileobj,
                                     tstate, f, PyTrace_RETURN, retval)) {
                Py_CLEAR(retval);
            }
        }
    }

この関数は、Pythonで書かれた関数を実際に実行するコードです。バイトコードの実行ループがあるので(今回の話とは一切無関係ですが)読んでいて面白い関数ではあります。おすすめです。

PythonからC言語の関数呼び出しは別扱い

C言語の関数の呼び出しは、もうちょっと複雑です。Pythonの内部で使われているVMのオペコードのうち、CALL_METHOD/CALL_FUNCTION/CALL_FUNCTION_KW/CALL_FUNCTION_EX命令が実行された時に呼ばれる、次の関数からC言語の関数の実行が移譲されています:

// https://github.com/python/cpython/blob/842a2f07f2f08a935ef470bfdaeef40f87490cfc/Python/ceval.c#L4648

/* Issue #29227: Inline call_function() into _PyEval_EvalFrameDefault()
   to reduce the stack consumption. */
Py_LOCAL_INLINE(PyObject *) _Py_HOT_FUNCTION
call_function(PyObject ***pp_stack, Py_ssize_t oparg, PyObject *kwnames)
{

    // ... 前処理 ...

    /* Always dispatch PyCFunction first, because these are
       presumed to be the most frequent callable object.
    */
    if (PyCFunction_Check(func)) {
        PyThreadState *tstate = _PyThreadState_GET();
        C_TRACE(x, _PyCFunction_FastCallKeywords(func, stack, nargs, kwnames));
    }
    else if (Py_TYPE(func) == &PyMethodDescr_Type) {
        PyThreadState *tstate = _PyThreadState_GET();
        if (nargs > 0 && tstate->use_tracing) {
            /* We need to create a temporary bound method as argument
               for profiling.
               If nargs == 0, then this cannot work because we have no
               "self". In any case, the call itself would raise
               TypeError (foo needs an argument), so we just skip
               profiling. */
            PyObject *self = stack[0];
            func = Py_TYPE(func)->tp_descr_get(func, self, (PyObject*)Py_TYPE(self));
            if (func != NULL) {
                C_TRACE(x, _PyCFunction_FastCallKeywords(func,
                                                         stack+1, nargs-1,
                                                         kwnames));
                Py_DECREF(func);
            }
            else {
                x = NULL;
            }
        }
        else {
            x = _PyMethodDescr_FastCallKeywords(func, stack, nargs, kwnames);
        }
    }
    else {
        // ... Pythonの関数のときの処理 ...
    }

    // ... 後処理 ...

    return x;
}

この最初の2つのif文がC言語で書かれた関数ないしメソッドの呼び出しに対応しているようです。2番めのPy_TYPE(func) == &PyMethodDescr_Type の方は、調べた限りでは、

>>> po = "po!"
>>> f = po.upper
>>> f()
'PO!'

のような感じで、メソッドにselfだけ束縛した場合に実行される分岐のようです(あんまり自信ない)。

C_TRACEというマクロの定義は次の通りで、callという引数で指定されるC言語関数呼び出しコールの前後でPyTrace_C_CALLとPyTrace_C_RETURNをプロファイラのコールバック関数に対して通知するようになっています。

// https://github.com/python/cpython/blob/842a2f07f2f08a935ef470bfdaeef40f87490cfc/Python/ceval.c#L4617

#define C_TRACE(x, call) 
if (tstate->use_tracing && tstate->c_profilefunc) { 
    if (call_trace(tstate->c_profilefunc, tstate->c_profileobj, 
        tstate, tstate->frame, 
        PyTrace_C_CALL, func)) { 
        x = NULL; 
    } 
    else { 
        x = call; 
        if (tstate->c_profilefunc != NULL) { 
            if (x == NULL) { 
                call_trace_protected(tstate->c_profilefunc, 
                    tstate->c_profileobj, 
                    tstate, tstate->frame, 
                    PyTrace_C_EXCEPTION, func); 
                /* XXX should pass (type, value, tb) */ 
            } else { 
                if (call_trace(tstate->c_profilefunc, 
                    tstate->c_profileobj, 
                    tstate, tstate->frame, 
                    PyTrace_C_RETURN, func)) { 
                    Py_DECREF(x); 
                    x = NULL; 
                } 
            } 
        } 
    } 
} else { 
    x = call; 
}

ここ以外にももっと複雑な関数呼び出しのためのdo_call_core関数もあるのですが、そっちもだいたい似た感じなので省略します。

Pythonの関数のCALL/RETURNは、呼び出された関数の中で記録されるのに対して、C言語の方は呼び出す直前なところがちょっと面白いところでしょうか。もちろん、C言語の関数はPythonのインタプリタから遠く独立していることを踏まえれば、合理的な実装だと思います。

オチはなし:意外と素朴な実装だったなぁ(小学生並みの感想)

…えー、とくにオチはないです。強いて言うなら、意外と素朴な実装でしたね。Linuxカーネルのよくわかんない機能とか使ってるのかなぁという予想も事前にしていたのですが、そんな事はなくて、地道に適当なタイミングで適切に関数を呼び出して記録しているだけでした。

cProfileとprofileの具体的な違いは?

Pythonでプロファイルを取る方法は、cProfileだけではなく、profileというのもあります。こちらは100% Pure Pythonで、cProfileが使えない環境ではこちらを使ってね、とドキュメントには書いてあります。こちらはどのような実装になっているのでしょうか?Pythonのインタプリタの奥深くにプロファイルのための機能が実装されている以上、profileもこれを使っていそうな気はするんですが…。

コードを調べると:

# https://github.com/python/cpython/blob/ad1a25f499362eaf9cbfcafa0b8e2454eb43dcf1/Lib/profile.py#L418

    def runctx(self, cmd, globals, locals):
        self.set_cmd(cmd)
        sys.setprofile(self.dispatcher)
        try:
            exec(cmd, globals, locals)
        finally:
            sys.setprofile(None)
        return self

案の定、sys.setprofileという、PyEval_SetProfileのPython版を使って、C言語の関数ではなくPythonの関数をcallbackとしているだけのように読めます。

1つの引数を取る関数をプロファイルしたい場合、次のようにできます:

import cProfile
import re
cProfile.run('re.compile("foo|bar")')

(お使いのシステムで cProfile が使えないときは代わりに profile を使って下さい)

Python プロファイラ — Python 3.7.3rc1

cProfileのコードはそんなにトリッキーな事をしているようには読めないので、cpythonがコンパイルできる環境ならcProfileも使えると思うんですが、cProfileが使えない環境は実際にあるのだろうか…。

いかがでしたか?

「だからなんだ」と言われればそれでオシマイなんですが、ソースコードを読むのはやっぱり重要だと痛感しました。ドキュメントにはすべては書いてないので。この記事が、いつか、cProfileの挙動に違和感を持った人の参考になりますように。

というわけで、次の記事では、マルチスレッドのPythonプログラムをプロファイルする方法を探していきます。