cProfileの先にあるもの。 パフォーマンス最適化のための正しいツールの選択

注：この記事は、PyGotham 2019で行った講演を基に書かれています。 動画はこちらからご覧いただけます。

あなたのPythonプログラムは遅すぎます。Webアプリケーションが追いつかない、または特定のクエリに時間がかかっているのかもしれません。

実行に何時間も何日もかかるバッチプログラムがあるのかもしれません。どうすれば高速化できますか?

1. 速度を測定するための適切なツールを選択します。
2. ボトルネックを修正する。

この記事では、最初のステップである正しいツールの選択に焦点を当てます。 Python 標準ライブラリの決定論的なプロファイラです。 サンプリングプロファイラ。 ロギングライブラリ.

これらのツールの使い方については、適切なものを選ぶ手助けをすることが目的なので、あまり詳しくは説明しません。 しかし、これらのツールが何をするのか、そして、いつ、なぜ、他のツールより 1 つを選択するのかを説明します。 cProfile プロファイラーは Python に組み込まれているので、おそらく聞いたことがあるでしょうし、デフォルトで使用しているツールかもしれません。CPU を測定するということは、データベースクエリの応答待ちのような、他の原因による遅さを検出することができないということです。もし、普段直接実行しているスクリプトがあれば、

$ python benchmark.py7855 messages/sec

そして、python -m cProfileをプレフィックスとしてつけるだけで、プロファイラの下で実行できます:

また Python プロファイリング API もあり、特定の機能を Python インタプリタのプロンプトや Jupyter notebook でプロファイルすることができます。

出力形式は表ですが、これは理想的ではありません。各行はプロファイルされた時間スパンで実行された関数呼び出しですが、その関数呼び出しが他の関数呼び出しとどのように関連しているかはわかりません。つまり、複数のコード パスから到達できる関数がある場合、どのコード パスが遅い関数の呼び出しに関与しているかを把握するのは困難です。

cProfile でわかること

上の表を見てみると、

• _output.py(__call__) が 50,000 回呼び出されていることがわかります。 これは、ループ内で同じコードを 10,000 回実行するベンチマーク スクリプトであるため、偶数回となっています。関数を意図的に何度も呼び出していない場合、呼び出し回数が多いことを発見するのに役立ちます。
• _output.py(send) は 0.618 CPU 秒（呼び出した関数の CPU 時間を含む）、および 0.045 CPU 秒（呼び出した関数を含まない）使用しました。
  

  How it works

  cProfile はすべての関数呼び出しを測定します。特に、実行中のすべての関数呼び出しは次のようにラップされます。

  The problems with cProfile

  cProfile はどの Python インストールでも常に利用できますが、いくつかの重大な問題にも悩まされています。

  問題点1: 高いオーバーヘッドと歪んだ結果

  想像できるように、すべての関数呼び出しに対して余分な作業を行うことは、いくつかのコストがかかります:

  $ python benchmark.py7855 messages/sec$ python -m cProfile benchmark.py5264 messages/sec... cProfile output ...

  cProfile の実行がどれだけ遅いか気づいていますか。さらに悪いことに、速度低下はプログラム全体で一様ではありません。関数呼び出しの数に関連しているので、より多くの関数呼び出しがあるコードの部分はより速度が低下します。

  問題点 2: 情報が多すぎる

  上で見た cProfile 出力を思い出してください、それはプログラム実行中に呼び出されたすべての関数の行を含みます。

  問題 3: パフォーマンスのオフライン測定

  多くの場合、プログラムは実世界の条件、実世界の入力で実行されたときのみ遅くなります。

  しかし、cProfile はあなたのプログラムをかなり遅くするので、おそらく実稼働環境では実行したくありません。

  問題その 4: パフォーマンスは関数に対してのみ測定される

  cProfile は「slowfunc() は遅い」と伝えることができますが、これはその関数へのすべての入力を平均化した値です。

  しかし、特定の入力に対してのみ遅いアルゴリズム コードがある場合もあります。

• slowfunc(0) が遅い。

cProfile では、どの入力で遅いのかが分からないため、問題の診断がより困難になる可能性があります。 その代わりに、次の 2 つの代替手段を紹介します。

• Pyinstrument は 1 番と 2 番の問題を解決します。

Pyinstrument: a sampling profiler

Pyinstrument は上記で取り上げた問題のうち 2 つを解決します:

• cProfile よりオーバーヘッドは低く、結果を歪めることはない。
• 無関係な関数呼び出しを除外するので、ノイズが少なくなります。

Pyinstrument は CPU 時間ではなく、経過した壁時計時間を測定するので、ネットワーク要求、ディスク書き込み、ロック競合などによる遅れを捕捉できます。

使い方

Pyinstrumentの使い方はcProfileと同様で、スクリプトにプレフィックスを追加するだけです:

$ python benchmark.py7561 messages/sec$ python -m pyinstrument benchmark.py6760 messages/sec... pyinstrument output ...

多少のオーバーヘッドはありますが、cProfileほどではなく、オーバーヘッドは均一であることに注意してください。

Pyinstrument は Python API も持っているので、Python インタラクティブ インタープリタまたは Jupyter ノートブックでコードの特定の部分をプロファイルするために使用することができます。

出力

Pyinstrument の出力は呼び出しのツリーで、壁時計の時間を測定します。

cProfile の row-per-function とは異なり、Pyinstrument は関数呼び出しのツリーを表示するので、遅さのコンテキストを見ることができます。

結果として、Pyinstrument の出力は cProfile のデフォルト出力よりもはるかに解釈が簡単で、プログラムのパフォーマンス構造についてよりよく理解することができます。

一瞬一瞬を盗み見ることもできますが、それは大変な作業です。そこで、サンプルを取ることにしました。5分ごとに猫がいる部屋に頭を突っ込み、何をしているかを書き留めます。

たとえば、

• 12:00: 寝る💤
• 12:05: 寝る💤
• 12:10: 食べる🍲
• 12:15: トイレの使用💩
• 12:20: 寝る💤
• 12.00: 寝る💤

12.10: 寝る

• 12.10: 食べる 12.10: 寝る 12.10: 寝る
• 12.11: 寝る。25：睡眠💤
• 12：30：睡眠💤

数日後の観察をまとめると、

• 80%です。 寝る 💤
• 10%: 食事中 🍲
• 9%: ゴミ箱を使う 💩
• 1%: 227>

  では、この要約はどれくらい正確なのでしょうか？あなたの目的が猫が最も長い時間を過ごした場所を測定することである限り、おそらく正確です。そして、観察（=サンプル）の頻度と観察回数が多いほど、要約はより正確となります。

  あなたの猫がほとんどの時間を寝て過ごすなら、ほとんどのサンプルの観測が寝ていることを示すと期待するでしょう。そして、はい、あなたはいくつかの迅速かつまれな活動を見逃しますが、「猫がその時間のほとんどを何に費やしたか」という目的のためには、それらの迅速かつまれな活動は重要ではありません。

  How it works (software edition)

  私たちの猫と同じように、Pyinstrument は Python プログラムの動作を間隔を置いてサンプリングします: 1ms 毎に、どの関数が現在実行されているかをチェックします。

• もし関数が累積的に速ければ、通常はまったく表示されません。

つまり、パフォーマンスの要約はノイズが少ないということです。ほとんど使用されていない関数はほとんどスキップされます。しかし全体的に要約は、十分にサンプルを取っていれば、プログラムが時間をどう使ったかという点でかなり正確です。 これは、cProfile で見られた他の 2 つの問題を解決します:

• Logging は実稼働環境で使用可能です。

おわかりのように、Eliot は通常のロギングライブラリよりもパフォーマンスを記録するのに適したいくつかのユニークな機能を提供します。

既存のコードにロギングを追加する

プログラムの次のスケッチを考えてみましょう：

このコードにロギングを追加します：

特に、2 つのことを行います：

1. log メッセージを出力する場所（この場合、 “out.log” というファイル）。
2. 私たちは @log_call デコレーターで関数を装飾します。これは、関数が呼び出された事実、その引数、および戻り値 (または発生した例外) を記録します。

Eliot には他にももっと細かい API がありますが、ロギングの利点を示すには @log_call で十分でしょう。

エリオットの出力

一度プログラムを実行すると、eliot-tree というツールを使ってログを見ることができます：

少し Pyinstrument のように、アクションのツリーを見ることに注意してください。もともとは、この記事の講演版で使用したスライドに収まるように出力を少し単純化しましたが、散文記事であってもパフォーマンスの側面に焦点を当てることができます。この場合、各アクションは関数呼び出しと 1 対 1 で対応します。また、Pyinstrument の出力といくつかの違いがあります。

1. 複数の関数呼び出しを組み合わせるのではなく、個々の呼び出しを個別に表示します。
2. 各呼び出しの引数と戻り値を確認できます。
3. 各アクションのウォールクロック経過時間を確認できます。

たとえば、multiplysum() には 10 秒かかりましたが、大半の時間は multiply() で、3と 4 の入力で費やされていることがわかります。そのため、パフォーマンス最適化のために multiply() に集中したいこと、および、弄るためのいくつかの開始入力 (3 と 4) があることがすぐにわかります。

ログの限界

ログは、パフォーマンス情報のソースとしてそれだけでは十分ではありません。Eliot は、tree-of-actions 構造がどこに時間が費やされたかをある程度理解できるため、これを少し良くしますが、ロギングがあまりにもまばらである場合、まだ十分ではありません。

次に、プログラムが遅くなるので、ログをどこにでも追加することはできません。ログは安くはなく、cProfile よりも高いオーバーヘッドとなります。

正しいツールを選択する

では、それぞれのツールをいつ使用すべきでしょうか。

常にログを追加する

自明ではないプログラムには、バグやエラーを発見するためだけであれば、おそらく何らかのログが必要でしょう。

Eliot は、アクションをログすることで本質的に経過時間を与えるので、より簡単ですが、いくつかの追加作業により、任意のログ記録ライブラリでこれを行うことができます。

• これはオーバーヘッドが少なく、さらに重要なのは結果を歪めないことです。

カスタムコスト指標が必要な場合は cProfile を使用する

カスタムプロファイラを書く必要がある場合、cProfile では異なるコスト関数を差し込むことができ、より珍しい指標を簡単に測定するツールになります。

TL;DR

パフォーマンス最適化ツールの良い出発点として、次のことをお勧めします:

1. Eliot やその他のログ記録ライブラリを使用して、主要な入力と出力、および主要なアクションの経過時間をログ記録することです。
2. デフォルトのプロファイラとして Pyinstrument または他のサンプリングプロファイラを使用する。