普段のラウンドは試験的にベンチマーク回して preview という形でMLに公開し、エラーや設定ミスを修正するサイクルを数回繰り返すんだけど、今回はベンチマークに使ってた PEAK Hosting 上のマシンが退役するということで、1回目の preview だったはずのベンチマーク結果がそのまま Round 12 になり、 Round 13 で仕切り直しになる模様。
個人的な今回の Round 12 の目玉は Go の fasthttp. 標準の net/http に比べて、設計の綺麗さという面では改悪し、API互換性もなくなってるけど、よりアグレッシブにメモリのアロケートを避けられるので速い。
Go 1.5, 1.6 では GC の停止時間が改善されたけど、 1.7 ではスループットの改善がされる予定なので、 Round 13 が Go 1.7 の後になるなら、 net/http がどこまで fasthttp との差を詰められるかが見もの。
あとは次回に PyPy3 と uWSGI+PyPy 構成を投入できると良いなぁ。
Go による Web アプリケーション開発 を読みました。 (まだ後半はパラパラめくっただけですが)
この本は Go のチュートリアルでは無いです。 A Tour of Go とか The Go Programming Language で基本的な文法などは抑えた状態で読むべきでしょう。
この本で最初のサンプルアプリケーションは、 WebSocket によるチャットです。まず単に動くだけのチャットを作ってから、 Github などと OAuth2 で認証したり、各所からアイコンを引っ張ってきたりと、 Go で小さめの Web アプリを作るときに実用されそうな要素が並んでいます。
後半のサンプルアプリケーション (Twitter と連携する voting アプリ)では MongoDB や NSQ を使いはじめるので、ちょっとそのミドルウェアを使わない人にとっての実用性が落ちてきます。しかしこれも、 LAMP とは違った構成でとりあえず動くものを作る上では参考になると思います。
課題の選び方にはとてもセンスが光っている一方、気になるのはコード等実装レベルでのセンスです。 early return イディオムを使ってない（これはGo以外でも可読性の高いイディオムですが、特にGoらしいプログラムでは必須です）とか、 エラー処理が抜けているとか、最初のサンプルアプリでユーザーが自分でアイコンをアップロードする場面でファイルのパーミッションを 0777 で保存していたりとか、 コードレベルでもそれ以外の部分でもたくさんの顔をしかめるポイントがありました。
しかし、気になったポイントのほとんどに鵜飼さんの「監訳注」が入って、細かくフォローされています。 さらには付録B「Goらしいコードの書き方」で、本文中のGoらしくないコードをGoらしくリファクタリングしていきます。 本文の翻訳の方も詰まらずにすらすら読めるものですし、原文よりも絶対に邦訳の方がオススメです。
例えばWeb企業で新人研修で1周間くらいでGoを教える場合には、 Tour of Go とこの本の最初のサンプルプログラムまでをセットにするのが良いと思います。
速い Python 実装といえば PyPy が有名ですが、 Python 3 へのキャッチアップが遅い、 CPython が持っている Python/C API のサポートがまだ弱く遅い、などの欠点があります。
また、 Google の1年プロジェクトだった Unladen Swallow もありました。これは CPython をフォークして LLVM で JIT を実装するものでした。この fork 実装は終わりましたが、この時期まだ不安定だったLLVMへの貢献は大きく、（ちゃんとおってないので憶測ですが）現代LLVMを利用したJITを実装しているプロジェクトは全部間接的に Unladen Swallow の成果の上に成り立っていると言えるかもしれません。
終了した JIT プロジェクトといえば、 psyco もありました。これはベタに CPython の JIT を実装していましたが、メンテが大変なのと PyPy に性能で追いぬかれたので終了しました。
他の速度を目的とした Python 実装としては Dropbox の Pyston があります。これも PyPy と同じく Python 2 がメインターゲットですし CPython との互換性も低いですが、より保守的な JIT を実装しています。最近 Nexedi が Pyston の開発に加わりました
また、 MicroPython という組み込み向けの Python もあります。これは CRuby と mruby の関係に似ていると思います。 CPython のしがらみに囚われずにいろいろな動的言語の高速化手法を取り込めるため、 CPython より速いのですが、PC上で普段使いとして使うにはライブラリのカバーしてる範囲が狭いのが欠点です。こっちは pyston と違って Python 3 の実装です。
最近活発な CPython を高速化するプロジェクトが2つあります。 FAT Python と Microsoft の Pyjion です。
FAT Python は CPython を高速化にしようとするプロジェクトです。 Ruby 2 系で行われているようなメソッドキャッシュの改良が試みられていたり、さらにアグレッシブに、 AST レベルでのインライン展開や定数の畳み込みといった試みをプラガブルにしようとしています。もちろん Python 3 ベースです。
Pyjion も CPython ベースで、 JIT エンジンを CPython に付けられる用にする、その JIT の参照実装というか実効性の検証用に、 CoreCLR を使ったJITを組み込もうというものです。 IronPython と違って Python そのものの .NET ベースの実装というわけではなくてあくまでも CPython の拡張を提案するプロジェクトです。 まだ詳細は発表されていませんが、もうすぐ PyCon で発表があるはずです。
個人的には、活発化してきた PyPy3 の開発が進んでくれることと、 FAT Python の成果の一部が Python 3.6 に間に合うことを期待しています。
ISUCON は Go で参戦しているんだけど、複数のチームが Python で予選通過したらしいので、応援のために Tips を公開していこうと思う。
目次
CPython のGCは参照カウント＋循環参照コレクタだ。そして参照カウント方式は(幾つかの欠点はあるものの)Webアプリのボトルネックになったりはしにくい。 なのでGCチューニングの基本は次のようになる。
循環参照コレクタは、生きているオブジェクトの数がある程度増えると第一世代が実行され、第一世代が一定回数実行されると第二世代が、第二世代が一定回数実行されると第三世代が実行される。
In [1]: import gc In [2]: print(gc.get_threshold()) (700, 10, 10) In [3]: gc.set_threshold(1000, 10, 10) In [4]: print(gc.get_threshold()) (1000, 10, 10)
デフォルトでは、700個オブジェクトが増えた時点で第一世代GCが起動し、第二世代と第三世代は前世代GCが10回起動する度に実行される。
重要なのは、第一世代GCが起動する条件が「循環参照してるオブジェクト」ではなく「生きてるオブジェクト」が増えた時だということだ。*1
例えば複雑なJSONを処理するプログラムでは、JSONは循環する構造を持っていないにもかかわらず、JSONデコード中に何度も循環参照コレクタが起動してスピードを落としてしまう。
プログラムのエントリーポイントなどで、GCが統計情報を出力するようにしておく。
import gc
gc.set_debug(gc.DEBUG_STATS)
これで標準エラー出力に、GCが実行される度に統計情報が出力される。
import gc
gc.set_debug(gc.DEBUG_STATS)
while True:
d = {}
d['key'] = d
... gc: collecting generation 1... gc: objects in each generation: 782 11 5083 gc: done, 791 unreachable, 0 uncollectable, 0.0001s elapsed ...
最初の行は、世代を0からカウントしているので1と表示されているので、第二世代のGCを開始していることを示している。
次の行は、GC実行前の各世代のオブジェクト数で、若いオブジェクトが782、第一世代GCを生き残ったオブジェクトが11、第二世代GCを生き残ったオブジェクトが5083あることを示している。
次の行で、 791 個のオブジェクトが unreachable (到達不能) で消されている。 0 uncollectable はすべての到達不能オブジェクトが回収できたことを示している。*2
Web アプリのような場合、リクエストごとにたくさんのオブジェクトを作っては捨てる。 Python の場合その殆どがリクエストの処理の終了時に参照カウントで自動的に回収されるはずだが、第一世代GCのしきい値が低いとそれらのオブジェクトのために循環参照GCが実行されてしまう。
本物のWebアプリの代わりに次のような簡単なサンプルを見てみる。GCの動作が見やすいようにしきい値は調整している。
import gc import sys gc.set_debug(gc.DEBUG_STATS) gc.set_threshold(500, 2, 2) def app(): x = [] for i in range(2000): x.append([]) def main(): for i in range(5): print('start:', i, file=sys.stderr) app() print('end', file=sys.stderr) main()
... start: 2 gc: collecting generation 0... gc: objects in each generation: 583 0 4759 gc: done, 0.0000s elapsed gc: collecting generation 1... gc: objects in each generation: 504 581 4759 gc: done, 0.0001s elapsed gc: collecting generation 2... gc: objects in each generation: 504 0 5842 gc: done, 0.0013s elapsed end start: 3 gc: collecting generation 0... gc: objects in each generation: 576 0 4750 gc: done, 0.0000s elapsed ...
このログを見ると、次の2つのことがわかる
N unreachable, が表示されていない)このことから、第一世代GCのしきい値を倍の2000程度にすれば、循環参照コレクタの起動を抑制できることがわかる。
import gc import sys gc.set_debug(gc.DEBUG_STATS) gc.set_threshold(2000, 2, 2) # ...以下同じ
start: 0 gc: collecting generation 1... gc: objects in each generation: 2041 4417 0 gc: done, 0.0009s elapsed end start: 1 end start: 2 end start: 3 end ...
最初だけ、多分 Python 起動時に1000個以上のオブジェクトを確保していたためにGCが起動しているが、その後のリクエストの処理では一切循環参照コレクタが実行されていないことがわかる。
循環参照オブジェクトがあって完全には循環参照コレクタを抑止できない場合もある。
その場合、 例えば GC を止める・Ruby ウェブアプリケーションの高速化 にあるように、レスポンスを返したあと、次のリクエストを受け取る前に循環参照コレクタを実行することで、GCの実行時間がレスポンスタイムに与える影響を最小限にすることができる。 (=Out of Band GC, OOBGC)
純粋な wsgi アプリケーションは関数呼び出し=アプリケーションの実行であるため凝ったことをしないと OOBGC ができないが、アプリケーションサーバーによっては OOBGC を可能にする hook を提供している。
特に uWSGI の場合、 uwsgi プロトコルで keep-alive なしで nginx の配下に置くのが一般的なので、OOBGCが完了したプロセスが次のリクエストを accept() することができるので効果的だ。
# wsgi.py import gc import uwsgi import myapp application = myapp.get_app() gc.set_threshold(10000, 10, 10) uwsgi.after_req_hook = lambda: gc.collect(1)
gc.DEBUG_STATS により、GCの実行時間が長く、また大量の unreachable が検出されている場合は、循環参照が原因だ。その場合は個別に循環参照を潰していく必要がある。
まずは循環参照を見つけるために、 gc.DEBUG_COLLECTABLE を使って、循環参照に入っていたオブジェクトの型を見る。
import gc gc.set_debug(gc.DEBUG_STATS | gc.DEBUG_COLLECTABLE) for _ in range(10000): d = {} d['key'] = d
... gc: done, 780 unreachable, 0 uncollectable, 0.0617s elapsed gc: collecting generation 2... gc: objects in each generation: 365 11 4750 gc: collectable <dict 0x7fe7be594d08> gc: collectable <dict 0x7fe7be58f048> gc: collectable <dict 0x7fe7be58c9c8> gc: collectable <dict 0x7fe7be589ac8> gc: collectable <dict 0x7fe7be589a88> gc: collectable <dict 0x7fe7be589a48> gc: collectable <dict 0x7fe7be589a08> gc: collectable <dict 0x7fe7be5899c8> gc: collectable <dict 0x7fe7be589988> gc: collectable <dict 0x7fe7be589948> gc: collectable <dict 0x7fe7be589908> ...
型だけではわからない場合、 gc.DEBUG_SAVEALL を使う。このオプションを使うと本来回収されるオブジェクトを gc.garbage というリストに入れてくれるので、コールバックで gc.garbage の中の注目してる型のオブジェクトの情報を表示して、 gc.garbage をクリアしてやる。
import sys import gc gc.set_debug(gc.DEBUG_STATS | gc.DEBUG_SAVEALL) @gc.callbacks.append def after_gc(phase, info): if phase == "start": return for o in gc.garbage: if isinstance(o, dict): print("gc dict keys=", list(o), file=sys.stderr) gc.garbage.clear() for _ in range(10000): d = {} d['key'] = d
... gc dict: ['key'] gc dict: ['key'] gc dict: ['key'] gc dict: ['key'] gc dict: ['key'] ...
これで、 'key' というキーを持つ dict が原因だとわかった。gc.garbage から見つけたオブジェクトがどうやって循環参照に加担しているかを調べるために、他にも gc.get_referrers() や gc.get_referents() がある。
さて、これで問題の dict が見つかった。循環参照を壊してやるには、使い終わった dict の .clear() メソッドを呼べばいい。
import sys import gc gc.set_debug(gc.DEBUG_STATS) for _ in range(10000): d = {} d['key'] = d ... d.clear()
GC方式の違いから、Python は Ruby に比べてWebアプリケーションでGCの時間がパフォーマンスに影響することは少ないが、大きいXMLを扱うアプリケーションをチューニングする場合や、数msを気にするチューニングの場合はこのような手段でGCのチューニングができる。
Go の logging ライブラリ、今はとりあえず標準ライブラリの log か google/glog を使っているんだけど、 log は機能不足が、 glog は Google 標準ライブラリなのでフォーマットを調整したり flag 以外でカスタマイズするために fork しないといけなかったりするので、他のロギングライブラリどれが良いか時々話題の logger を覗いてみていた。
結果、もう logrus で良いかなーと思っているんだけどそれはいったん置いておいて、選定基準の1つのパフォーマンスについて書いておく。
logger のパフォーマンスで一番重要なのは、ログを書かない時のパフォーマンスだ。 デバッグ用の詳細なログをいたるところに散りばめているアプリケーションでも、ログレベルを WARN にしておけば、 DEBUG レベルのログがパフォーマンスに与える影響を最低限にできるべきだ。
そのために理想的な logger の持つべき機能をまとめてみる
高機能なログライブラリは大抵、 logger が record を作成し、 handler に渡すという構成になっている。 handler はログを設定された通りにフォーマットしてテキストファイルに出力したり、エラーがあったらメールを送信したりする。
handler によって処理が異なるため、ログに必要な情報を全てまとめたものが record になる。 リッチな logger だと record がトレースバックなどの取得にコストがかかる情報を持っていたりするが、それが handler に利用されないと無駄になる。
logger が level を持つことで、 record の生成自体をスキップして、高コストな情報の取得を避けたり、不要オブジェクトの生成をせずにGCに優しくなることができる。
logger の level は必ずしも handler と別に設定できる必要はない。例えば handler の level を変更不可能にすれば、 logger に handler を追加するAPIで、 logger に登録されている handler の中で一番詳細なログレベルを logger の level にすることができる。
「高コストな情報取得」はトレースバックだけではない。ログの中に含める情報の取得にコストがかかるケースも有る。
その場合、 logger の呼び出し自体を、 logger のログレベルで回避する必要が出てくる。 glog は type bool Verbose を使って上手くこれを実装している。
glog.V(2).Infof("val: %v", veryHeavy()) // ログが書かれない場合も veryHeavy() が呼ばれる if glog.V(2) { glog.Infof("val: %v", veryHeavy()) // これなら呼ばれない。 }
logrus も、glog ほどかっこ良くも無ければ効率も良くない (mutex 使ってるので) が、呼び出し自体のショートカットが可能だ。
if logrus.GetLevel() >= logrus.DebugLevel { logrus.Debugf("val: %v", veryHeavy()) }
最近は structured logging が人気だ。通常のテキストログが printf 形式でログのメッセージの中に値を直接埋め込むのに対して、 structured logging ではメッセージは固定文字列にして付加情報として key: value を持つ。
これは、ログをJSONやLTSVなどの形式にして後から利用しやすいという利点もあるし、出力形式が文字列フォーマットよりも軽い場合はテキストログに比べて性能が上がるケースも有る。
でも大抵の場合、何らかのデータ構造へのシリアライズはテキストフォーマットより重くなりがちだし、しかも logger に任意の key: value 形式の値を渡すためにたくさんの一時オブジェクトを利用してしまう (GCへの負荷が増える) ことになりがちだ。
logrus の structured logging は次のような API になっている。
log.WithFields(log.Fields{
"animal": "walrus",
"size": 10,
}).Info("A group of walrus emerges from the ocean")
log.Fields は map[string]interface{} なので、このAPIだと (Info() が出力されない場合ですら) map が生成されてしまうし、しかも interface{} に入った value 側の変数は全部エスケープ解析でエスケープすると判断される可能性が高く、本来ヒープアロケートが一切必要ないようなローカル変数ですらヒープにアロケートされてGCに負荷をかけてしまうだろう。
mgutz/logxi はより効率の良い structured logging の API を提供している。
log.Info("A group of wairus emerges from the ocean", "animal", "walrus", "size", 10)
プログラムのミスで key: value が逆になってしまう可能性に目を瞑れば、短くて効率がいい。 logrus に比べるとあまり使われてないし機能も少ないけど、性能と structured logging が絶対に必要であれば一考に値する。
