Python の新しいプロファイラ vmprof が面白い

PyPy 2.6 と同時に、 vmprof という CPython/PyPy 用のプロファイラが登場しました。

私はまだ PyPy では使っていませんが、CPythonのプロジェクトをこれでプロファイル取ってみたらなかなか面白かったので紹介します。

概要

Python にはもともと標準ライブラリとしてプロファイラ (cProfile) が付いてきていますが、これは関数の呼び出しと戻りでコールバック関数を呼び出しつつ実行時間を計測するタイプのプロファイラで、短時間でも正確なプロファイルが取れる反面、オーバーヘッドが大きく、小さい関数をたくさん呼び出す部分がオーバーヘッドでより大きく見えてしまうなどの問題がありました。

これと別の種類のプロファイラとして、定期的にサンプリングして、サンプルが多いところが実行時間も多いハズ、というプロファイラもあります。こちらはある程度の量のサンプルを集めないと正確性にかけるものの、オーバーヘッドが小さく、小さい関数をたくさん呼び出す場合も正確にプロファイルができたり、本番環境のサーバーのプロファイルを取ることができたりします。 Go 言語の pprof もそうですし、 Python では私も昔に sigprofiler というものを作ったことがあります。

vmprof もこのサンプリング型のプロファイラです。 PyPy だときっと JIT の状態が見れるなどの特長があるのでしょうが、私は今のところ CPython で使っています。 CPython 用としてみた場合の vmprof の特長は次のような感じです。

  • Pythonのスタックと同時にCのスタックも保存して、同時に見ることができる
  • Python スタックを取る部分も C で実装されており、 sigprofiler よりずっと軽い

vmprof は Python スタックを取るために、 PyEval_EvalFrameEx をトランポリン関数で置き換えます。 SIGPROF シグナルハンドラでCのスタックを解析するのですが、その際にトランポリン関数を見つけるとその引数である frame オブジェクトを見つけて、 frame オブジェクトから Python のスタックを取ります。

(ちなみに、 CPython 用の部分とそれ以外が綺麗に分かれているので、他のインタプリタ型言語でも関数呼び出しの際に呼ばれる関数をセットしたら vmprof が使えるはずです)

C の関数呼び出しは Python の関数呼び出しよりずっと軽いので、トランポリン関数が1つ挟まるだけならほとんどオーバーヘッドはありません。

vmprof-server

コマンドラインでも簡単な出力を見れますが、 vmprof の本領を発揮するにはビジュアライザである vmprof-server が必要です。 これは Django REST framework とシングルページアプリケーションの組み合わせになっています。

他人に見られてもいいなら デモサイト が利用できますし、見られたくないなら自分で簡単にセットアップすることができます。

$ git checkout git@github.com:vmprof/vmprof-server.git
$ cd vmprof-server
$ pip install -r requirements/base.txt
$ ./manage.py runserver

これを使って、次のようなプログラムのプロファイルを取ってみましょう。

import time

def sum1(n):
    return sum(range(n))

def sum2(n):
    return sum(range(n))

def sum12(n, m):
    z = 0
    for _ in range(1000):
        z += sum1(n) + sum2(m)
    return z

def foo():
    return sum12(10000, 100000)

def bar():
    return sum12(30000, 10000)

def main():
    t0 = time.time()
    while time.time() < t0 + 10:
        foo()
        bar()

if __name__ == '__main__':
    main()
$ python -m vmprof -n --web http://vmprof.baroquesoftware.com/ ex2.py

デモサイト

f:id:methane:20150609223332p:plain

このプログラムで、 sum12() は sum1() と sum2() を呼び出していますが、その呼び出し比率は引数によって変わります。そして foo() と bar() が sum12() を呼び出していますが、引数が違うのでその内訳が違うはずです。

vmprof と vmprof-server は sum12() の中身の内訳をまとめてしまわず、ちゃんとスタックを維持してビジュアライズしてくれるのがわかると思います。

例えば ORM を利用している場合、クエリをコンパイルしてる部分と、オブジェクトをフェッチする部分の重さの比率を見ることで、たくさんオブジェクトをロードしてるから重いのか、複雑なクエリをコンパイルしているから遅いのかを判断することができます。

まだまだ未完成なプロジェクトですが、わかって使えばとても強力なので、使ってみて足りない部分にプルリクエストを送ったりして応援していきましょう。

PyMySQLのメンテナにSQLAlchmey開発者のMike Bayer (@zzzeek)さんが参加しました

このブログでも数回紹介していたとおり、今メジャーな PythonMySQL ドライバ3つのうち2つ (MySQL-python の fork の mysqlclient と PyMySQL) を僕がほぼ単独でメンテナンスしている状況でした。

メンテナンスしているといっても、両方とも MySQL-python との互換性を第一に掲げているので、 Python 3 対応が終わった後はほとんど進化は無くて、淡々とバグの修正を積み重ねては1年に1度以上リリースするという程度です。

実際には Python では PostgreSQL 周りに比べて MySQL 周りは遅れていて幾つか改善案はあったのですが、子育てや他にも Python でやりたい事があったり仕事でも Go で楽しんでたりして手を付けられていませんでした。

そんな状況の中、 Mike さんが PyMySQL-Users ML に突然投稿をされました。 OpenStackの開発でPyMySQLを利用する事を検討していて、問題点・改善点が上がっているんだけど、PyMySQL側にプルリクエストなどを受け入れる準備があるかどうかを質問するものでした。

もともとmysqlclientとPyMySQLも個人でメンテナをするべきでないと思っていましたし、MikeさんはPythonで一番高機能なORMであるSQLAlchemyの開発者、そしてOpenStackといえば今Pythonで最も活発なプロジェクトの1つと呼べる巨大プロジェクトです。このチャンスを逃す手はありません。すぐにGithubのPyMySQL Organization に追加することを提案し、快諾してもらいました。

PyMySQLは性能や非同期対応についてのアイデアがあって、これはまさに OpenStack でも求められているものなので、これからOpenStackコミュニティと協力して進化させていこうと思います。

一方 mysqlclient は、最近 MariaDB が非同期APIを追加した MySQL Connector/C をリリースしているので、それに対応させる手段を検討していたのですが、ビルド時に上手く検出できるのか、PyPyでの速度を上げるために ctypes か cffi を使う別プロジェクトを fork するべきか、その場合 CPython では速度低下するけどどうするか…といった問題があり、メンテナンスコストと両立する解決策が見つかってなかったので、これを機に考えるのをやめることにします。

json.dump() は ensure_ascii=False の方が遅かった

Python の標準ライブラリの json モジュールのエンコード機能には ensure_ascii というオプションがあり、デフォルトでは True です。このオプションが真のときは、非ASCII文字を全て "\uXXXX" の形にエスケープします。

ensure_ascii=True の方が安全ですが、DBにjsonシリアライズしたデータを突っ込むなどの用途ではFalseの方がコンパクトになるし、日本語等を含む場合にエスケープされずに読みやすいので、 ensure_ascii=False を多用していました。

ensure_ascii=False はエスケープ処理が減る分速度も向上すると特に実験もせずに信じていたのですが、社内のプロジェクトで ensure_ascii=True の方が圧倒的に速いという報告を受けて、確認してみたら確かに ensure_ascii=True の方が速かったです。

ソースコードを確認したところ、 ensure_ascii=False の場合はエスケープ処理を正規表現の置換で行う一方、 ensure_ascii=True の場合は _json という speedup モジュールを使って高速に処理していました。

ensure_ascii=False の場合用の speedup 関数を追加するパッチを作って 報告 しておいたので、取り込まれれば Python 3.5 からは同等以上の速度になるはずです。

追記

コミットされました

Issue #23206: Make ``json.dumps(..., ensure_ascii=False)`` as fast as th... · ae9739e · python/cpython · GitHub

Python 3.3 以上で使える Python/C API で文字列アクセスを高速化

試しに英語で Blog を書いてみた のですが、書くので精一杯で結局何が言いたいのか分からない感じになってしまったので今後は日本語 Blog 書いてから英訳しようと思います。

Python 3 は 3.2 まで、文字列を unicode に統一した関係で Python 2.7 に比べて遅くなったりメモリ効率が悪くなったりしてしまっていたのですが、 Python 3.3 で PEP 393 Flexible String Representation が導入されて改善されました。

PEP 393 は Python の内部だけではなく Python/C API にも変更を加えており、内部を理解しつつ新しい API を適切に使えば、バイト列と文字列の間の変換を行うような C 拡張を高速化することができます。 そろそろ Python 3.2 のサポートを切れる時期なので、思い当たる人は目を通しておきましょう

PEP 393 の概要

PEP 393 では文字列オブジェクトの内部表現が幾つかに分かれています。

Compact (非 ASCII)

Compact は一番基本的な unicode オブジェクトです。

+--------+--------+------+-------+------+-------------+------+-------------+------+
| Header | length | hash | state | wstr | utf8_length | utf8 | wstr_length | DATA |
+--------+--------+------+-------+------+-------------+------+-------------+------+

Header:      Python オブジェクト共通のヘッダ
length:      文字列長 (codepoint数)
state:       各種フラグ
hash:        ハッシュ値キャッシュ
wstr:        wchar_t* 表現のキャッシュ
utf8_length: utf-8 にエンコードした時のバイト長
utf8:        utf-8 表現のキャッシュ
wstr_length: wstr の長さ
DATA:        NUL 終端したコードポイント列

DATA 内の各 codepoint を何バイトで表現するかは、その文字列が含む最大の codepoint によって 1byte, 2byte, 4byte のどれかが切り替わります。 これを kind と呼んで、 state で管理しています。 例えば文字列の codepoint が 0~255 の範囲に収まる場合、 1BYTE_KIND となり、DATA の大きさは NUL 終端を含めて文字列長+1 byte になります。

wstr と utf8 は、それぞれエンコードした結果のキャッシュです。 これは PyUnicode_AsUTF8() などの API を呼び出した時に生成されます。例えば utf8 は次のようなコードで生成されています:

    if (PyUnicode_UTF8(unicode) == NULL) {
        assert(!PyUnicode_IS_COMPACT_ASCII(unicode));
        bytes = _PyUnicode_AsUTF8String(unicode, "strict");
        if (bytes == NULL)
            return NULL;
        _PyUnicode_UTF8(unicode) = PyObject_MALLOC(PyBytes_GET_SIZE(bytes) + 1);
        if (_PyUnicode_UTF8(unicode) == NULL) {
            PyErr_NoMemory();
            Py_DECREF(bytes);
            return NULL;
        }
        _PyUnicode_UTF8_LENGTH(unicode) = PyBytes_GET_SIZE(bytes);
        Py_MEMCPY(_PyUnicode_UTF8(unicode),
        PyBytes_AS_STRING(bytes),
        _PyUnicode_UTF8_LENGTH(unicode) + 1);
        Py_DECREF(bytes);
    }

    if (psize)
        *psize = PyUnicode_UTF8_LENGTH(unicode);
    return PyUnicode_UTF8(unicode);

このコードを読めば分かるように、一旦 PyUnicode_AsUTF8String()utf-8エンコードした bytes オブジェクトを作ってから、その中身を malloc して確保した領域に memcpy しています。 繰り返し利用される場合以外は PyUnicode_AsUTF8String() を使って自前で bytes オブジェクトの中を見たほうが速くて省メモリです。

Compact ASCII

文字列に含まれる文字が ASCII である場合、次のような等式が成り立ちます。

  • utf8_length = length
  • utf8 = DATA
  • wstr_length = length

そのため、 Compact から要らない要素を取り除いた特別な表現を利用します。

+--------+--------+------+-------+------+------+
| Header | length | hash | state | wstr | DATA |
+--------+--------+------+-------+------+------+

utf8 キャッシュが存在せず、 PyUnicode_AsUTF8()PyUnicode_AsUTF8AndSize() は直接 DATA を返すので常に高速です。

Legacy

PEP 393 によって deprecated になった API のために用意された、古い構造です。 PyUnicode_Ready() で Compact 形式にインプレイス変換できます。

事例1: UltiraJSON

UltraJSON は高速な JSON エンコーダ/デコーダです。

典型的な JSON は多くの ASCII 文字列を含みます。 そして Compact ASCII 表現の場合、 utf8 へのエンコードをスキップすることができます。 それ以外の場合は、 PyUnicode_AsUTF8String() を使って bytes 型に変換してやります。

# https://github.com/esnme/ultrajson/pull/159
diff --git a/python/objToJSON.c b/python/objToJSON.c
index e56aa9b..a5b2f62 100644
--- a/python/objToJSON.c
+++ b/python/objToJSON.c
@@ -145,7 +145,17 @@ static void *PyStringToUTF8(JSOBJ _obj, JSONTypeContext *tc, void *outValue, siz
static void *PyUnicodeToUTF8(JSOBJ _obj, JSONTypeContext *tc, void *outValue, size_t *_outLen)
{
   PyObject *obj = (PyObject *) _obj;
-  PyObject *newObj = PyUnicode_EncodeUTF8 (PyUnicode_AS_UNICODE(obj), PyUnicode_GET_SIZE(obj), NULL);
+  PyObject *newObj;
+#if (PY_VERSION_HEX >= 0x03030000)
+  if(PyUnicode_IS_COMPACT_ASCII(obj))
+  {
+    Py_ssize_t len;
+    char *data = PyUnicode_AsUTF8AndSize(obj, &len);
+    *_outLen = len;
+    return data;
+  }
+#endif
+  newObj = PyUnicode_AsUTF8String(obj);
   if(!newObj)
   {
     return NULL;

このパッチの効果をマイクロベンチマークで確認してみます:

$ # Before
$ python3.4 -m timeit -n 10000 -s 'import ujson; x = ["a"*10]*100' 'ujson.dumps(x)'
10000 loops, best of 3: 15.8 usec per loop

$ # After
$ python3.4 -m timeit -n 10000 -s 'import ujson; x = ["a"*10]*100' 'ujson.dumps(x)'
10000 loops, best of 3: 7.14 usec per loop

事例2: Meinheld

Meinheld は高速な WSGI サーバーです。

HTTPヘッダのフィールド名は RFC で ASCII 文字列だと定義されていて、フィールド値はバイト列ですが PEP 3333 で latin-1 として扱うと定義されています。

HTTP ヘッダを作る場合は、 "HTTP_ACCEPT_ENCODING" のような文字列を作る必要があります。 受信バッファには "accept-encoding" のような文字列が入っているので、インプレイスで大文字化と - から _ への変換を行っても、 HTTP_ をつけることができません。 この場合、 PyUnicode_New(length, maxchar) の第二引数に 127 を与えると Compact ASCII 形式の空の unicode オブジェクトを作ってくれるので、 そこに対して直接文字列を書き込む事で "HTTP_" をつけるためだけに受信バッファと別に中間バッファを挟む必要がありません。

一方 HTTP フィールド値の方は "HTTP_" のような prefix をつけたりしないので、 PyUnicode_New() を使わなくても直接受信バッファから unicode を生成できます。 PyUnicode_DecodeLatin1() を使えば、実際に受信バッファに ASCII 外の文字があるかどうかによって自動的に Compact ASCII か Compact かを選んで生成してくれます。

逆に unicode から HTTP ヘッダを生成する場合も、unicode が ASCII か Latin-1 でない場合はエラーにできるので、 DATA 部分を直接 writev(2) に渡すことができます。

static int
wsgi_to_bytes(PyObject *value, char **data, Py_ssize_t *len)
{
#ifdef PY3
    if (!PyUnicode_Check(value)) {
        PyErr_Format(PyExc_TypeError, "expected unicode object, value "
        "of type %.200s found", value->ob_type->tp_name);
        return -1;
    }
    if (PyUnicode_READY(value) == -1) {
        return -1;
    }
    if (PyUnicode_KIND(value) != PyUnicode_1BYTE_KIND) {
        PyErr_SetString(PyExc_ValueError,
        "unicode object contains non latin-1 characters");
        return -1;
    }
    *len = PyUnicode_GET_SIZE(value);
    *data = (char*)PyUnicode_1BYTE_DATA(value);
    return 0;
#else
    return PyBytes_AsStringAndSize(value, data, len);
#endif
}

meinheld の主に http ヘッダ生成側を最適化してベンチマークしたところ、だいたい 23.5k req/sec から 25k req/sec へパフォーマンスが向上しました。

ちなみに前回 picohttpparser の比較で Python 2.7 を利用したのは、ヘッダパース部分をリライトするときに新APIを使ってしまったため、 Python 3 では純粋に HTTP パーサーの性能差を見ることができなかったためです。 今回は逆に picohttpparser 化前のソースコードを最適化したので、ヘッダパース側の最適化は手を抜いています。完全に最適化したらもう少し差が広がると思います。

最適化前:

$ ./wrk http://localhost:8000/
Running 10s test @ http://localhost:8000/
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   385.68us   25.67us 843.00us   74.12%
    Req/Sec    12.42k   632.30    13.78k    59.64%
  234475 requests in 10.00s, 39.13MB read
Requests/sec:  23448.18
Transfer/sec:      3.91MB
$ ./wrk http://localhost:8000/
Running 10s test @ http://localhost:8000/
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   379.78us   24.96us   0.90ms   73.86%
    Req/Sec    12.46k   639.91    14.00k    52.45%
  235688 requests in 10.00s, 39.33MB read
Requests/sec:  23569.38
Transfer/sec:      3.93MB
$ ./wrk http://localhost:8000/
Running 10s test @ http://localhost:8000/
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   388.15us   24.65us 524.00us   73.31%
    Req/Sec    12.43k   623.66    13.78k    55.26%
  234899 requests in 10.00s, 39.20MB read
Requests/sec:  23490.25
Transfer/sec:      3.92MB

最適化後:

$ ./wrk http://localhost:8000/
Running 10s test @ http://localhost:8000/
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   339.98us   65.87us   4.33ms   92.45%
    Req/Sec    13.56k     1.43k   15.44k    81.82%
  253189 requests in 10.00s, 42.26MB read
Requests/sec:  25319.67
Transfer/sec:      4.23MB
$ ./wrk http://localhost:8000/
Running 10s test @ http://localhost:8000/
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   364.82us   78.85us   1.01ms   84.10%
    Req/Sec    12.99k     1.81k   15.44k    80.63%
  243685 requests in 10.00s, 40.67MB read
Requests/sec:  24368.90
Transfer/sec:      4.07MB
$ ./wrk http://localhost:8000/
Running 10s test @ http://localhost:8000/
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   329.00us   22.40us 464.00us   73.99%
    Req/Sec    13.66k   760.36    15.44k    61.95%
  258730 requests in 10.00s, 43.18MB read
Requests/sec:  25873.60
Transfer/sec:      4.32MB

http-parser と picohttpparser との比較

h2o Advent Calendar 2014 の記事です。

Minefield は http-parser (nginx のパーサーと基本的に同じもの) を利用しているのですが、これを picohttpparser に置き換えてみます。 最初は libh2o に置き換えるつもりだったのですが、まだ API が unstable でアプリに組み込む手順も確立されてないので parser だけを置き換えることにしました。

まだ完成していないのですが、 Hello, World くらいは問題なく動くレベルになったので、ここまでで気づいた http-parser と picohttpparser の違いを紹介し、ベンチマーク対決もやってみます。

特に置き換えを始める前は、 perf top で execute_http_parser という http-parser の関数が2%程度しかCPUを消費していないのを見て、実際にサーバーの性能に与える影響については懐疑的だったのですが、実際に置き換えてみると意外に影響が大きいことが分かりました。

イベントドリブン vs シーケンシャル

http-parser はイベントドリブンで、ヘッダのフィールド名、フィールド値など個々にコールバック関数が呼ばれます。毎回与えられた受信バッファを完全に消費する設計になっているので、フィールド名の途中までで一旦コールバックが呼ばれ、次に受信バッファを与えた時にまたフィールド名の続きがコールバックされるかもしれません。

一方 picohttpparser は、ほぼステートレスで、ヘッダを一気にパースしますす。パース結果は受信バッファ上の位置と長さという形で返されるので、ほぼゼロコピーになっています。 (1度に read できなかった場合、2度め以降は前回読み込んだ位置より後ろに HTTP ヘッダの終端があるかどうかをチェックするので、「前回読み込んだ位置」が唯一の状態になります)

http-parser の状態管理や追記に対応するためのデータ構造やコードが面倒で、パーサー本体よりもこちらのほうが性能に影響を与えそうです。 頭のなかに状態表を持ってないとコードが読めないのでメンテナンス性の問題もあります。 picohttpparser にすることで、最初から完全に揃ったヘッダを受け取れるのでかなりコードをシンプルにすることが出来ました。

一方、 http-parser は毎回受信バッファを完全に消費するので1つのバッファをスレッド or プロセス全体で使いまわせるのですが、 picohttpparser では1度の read でヘッダ全体を受信できなかった場合にその受信バッファを保持しておく必要が生じます。

Minefield ではとりあえずコネクションごとに 32KB の read buffer を用意しましたが、 keep-alive 中のコネクションにこのバッファを確保し続けるのはもったいないのでもう少し賢く管理する必要があります。 Minefield は http pipelining にも対応しているので、受信バッファの管理は特に難しい問題になります。

HTTP/1.1 に対する知識

http-parser では、リクエストメソッドenum で渡してもらえますし、リクエストボディも callback で渡されます。

一方 picohttpparser では、リクエストメソッドも先頭位置と長さだけが渡されますし、リクエストボディも自分で処理する必要があります。自分で Content-Length ヘッダや Transfer-Encoding: chunked ヘッダを見つけて、指定バイト数読み取るか、 phr_decode_chunked() するかを決める必要があります。

この点は HTTP/1.1 の仕様の多くをパーサー側でカバーしてくれている http-parser の方が簡単ですし、脆弱性を作りにくく堅牢になると思います。

既存の http-parser を使ったアプリを picohttpparser に移植する際に問題になりそうなこと

HTTP/1.1 の知識が分散することもそうですが、バッファに関する制限が変わり、サーバーの仕様に影響を与えそうです。

どういうことかというと、 http-parser ではヘッダ名、ヘッダ値ごとに callback が呼ばれ、追記される可能性があるので、1つのヘッダの大きさを制限したくなります。最大長が決まっていれば、追記を許すと言ってもリアロケーションが不要になるからです。 一方 picohttpparser では、ヘッダを一括でパースするので、個々のヘッダの大きさよりもヘッダ全体の大きさを制限して、受信バッファの大きさを固定したくなります。

このため、パーサーの置き換えは Apache 2.2 -> 2.4 のような大規模なバージョンアップのタイミングで行った方がよいでしょう。

ベンチマーク

おまちかねのベンチマークです。 Gazelle vs Meinheld と同じ環境 (c3.xlarge) を使い、 wrk から Minefield の並列数は16ずつにします。

nginx が間に入ると Minefield の性能の変化が見えにくくなるので、直接アタックするのみにします。ただし、前回同様の keep-alive に加えて、今回はより性能が上がる(パーサー部分の負荷も増える) pipelining も試してみます。

ベンチマーク詳細 (各4回計測し、2番めに性能が高かった数値を採用)

parser keep-alive pipeline
http-parser 545552.78 782338.04
picohttpparser 567908.05 818628.66

f:id:methane:20141222122716p:plain

4% 強の性能向上が観測できました。今後完成度を高めていく上で、より picohttpparser に最適化されることで性能が上る可能性と、まだケアできてない HTTP/1.1 の仕様を実装することで速度が下がる可能性の両方がありますが、おおまかな目安にはなると思います。

このブログに乗せているコードは引用を除き CC0 1.0 で提供します。