2016年03月08日

Tornado アプリのログファイル書き込みのチューニング

はてなブックマークに登録

最近は協力プレイやPvPなどの「リアルタイムサーバー」を書くときは Go が主流になっているのですが、 Tornado を使ったシステムも健在です。 (以前の記事)

数人〜十数人程度の「部屋」を、1つの Tornado プロセスに複数もたせ、さらに一台のサーバーにその Tornado プロセスを複数置くことでCPUのマルチコアを活用する構成になっているのですが、最近各プロセスがログファイルを書く部分でブロックして応答性能が悪化するケースがあったので対策しました。

この記事ではその対策で行ったチューニングや、行わなかったチューニングについても紹介します。

※なお、この記事は Tornado を題材にしていますが、似たような仕組みになっている node.js などの他の言語のフレームワークでも同じ事が言えるはずです。

前提知識

Tornado は epoll や select などのIO多重化システムコールを利用したネットワークアプリケーション用のフレームワークです。

IO多重化はソケットなどのノンブロッキングIOと組み合わせたときは上手く行くのですが、ファイル書き込みはノンブロッキングIOにはできません。 epoll や select が「書き込み可能」と判断しても、実際に書き込もうとするとOSにブロックされてしまうことがあります。

とはいっても、ファイル書き込みは常にブロックするわけではありません。書き込み量やディスクの性能、メモリ量などによってはブロックしないことも多いです。なので、何も問題が起こってないなら Tornado アプリでも普通にログをファイルに書いていて良いのですが、 write がブロックするようになったなら IO 多重化を行っているループを阻害しないように対策をする必要があります。

write でブロックが発生しているかどうかは、 CPU の iowait が発生しているかどうかで調べることができます。さらに strace を使えばどの write が主なブロック要因になっているのかも調べることができます。

対策1: ログ書き込みを別スレッドで行う

ioloop が回っているメインスレッドでファイルへの write を直接行うと、そこでブロックしたときに全体が止まってしまい、応答性能が悪化してしまいます。 write を別スレッドで行えば、 write のブロックに ioloop が引きずられなくなるはずです。

今回問題になったアプリは Logbook というログライブラリを使っていました。このライブラリには標準で、ログ書き込みを専属のスレッドで行う仕組みがあるので、それを使えば既存コードに2行足すだけでログ書き込みの別スレッド化ができました。

import logbook
from logbook import FileHandler
from logbook.queues import ThreadedWrapperHandler  ## ThreadedWrapperHandler を import し

handler = FileHandler('application.log')
handler = ThreadedWrapperHandler(handler)          ## 既存の Handler をラップする
handler.push_application()
...

これでだいぶ応答性能は改善したのですが、この方法だとログを1つずつスレッド間通信が挟まるので、オーバーヘッドが大きく、CPU効率があまり良くありません。 Python は C言語と比べてスレッドの切り替えコストが高いのです。

対策2: ログ書き込みをパイプ経由で別プロセスで行う

ファイルへの書き込みがブロックする条件は複雑(あとで少し触れます)なのですが、パイプへの書き込みはパイプバッファ (一般的な Linux では多分64KB) がいっぱいになるまでブロックしません。

さらに、プロセスを分けてコマンドを実行する方式なら gzip 圧縮などを効率よく実行できます。 gzip 圧縮は Python 内で別スレッドで処理することができますが、スレッド間でのやりとりをバッファリングして大きな粒度で行うなどの最適化を行わなければ、「対策1」と同じくオーバーヘッドが大きくなってしまいます。それに対してパイプへの書き込みなら通常のファイルIOと同じ仕組みを使って簡単にブロックバッファリングが可能です。

また、パイプへの書き込みはファイル書き込みと違ってノンブロッキングIOにすることができるので、ソケットと同じように効率的に多重化することもできます。そこまでやれば、 gzip からの書き込みが詰まって、 gzip へのパイプまで詰まることになっても、 ioloop をブロックせずに済みます。

今回は gzip 化することで iowait が消え去ったのと、 gzipへのパイプまで詰まるようなスペックのサーバーではそもそも安定してサービスできないだろうという事で、よりシンプルな直接パイプへ書き込む方式を採用しました。 利用した Logbook でパイプ経由で gzip 圧縮するログハンドラのコードはこちらです。

import subprocess
import logbook
from logbook.helpers import is_unicode

class GZFileHandler(logbook.FileHandler):
    """GZFileHandler is FileHandler compressing output via piped gzip command"""

    proc = None

    def __init__(self, filename, complevel=9, **kwargs):
        kwargs['delay'] = False
        logbook.FileHandler.__init__(self, filename, **kwargs)

        cmd = ["gzip", "-" + str(complevel)]
        self.proc = subprocess.Popen(cmd, bufsize=-1,
                                     stdin=subprocess.PIPE,
                                     stdout=self.stream.fileno(),
                                     close_fds=True)

    def write(self, item):
        if is_unicode(item):
            item = item.encode(self.encoding)
        self.proc.stdin.write(item)

    def close(self):
        self.proc.stdin.close()
        self.proc.wait()
        logbook.FileHandler.close(self)

handler = GZFileHandler('application.log.gz')

「対策1」のコードとパフォーマンスを比較しましょう。ベンチマークでは、単純に100万回ログを出力します。

def main():
    for i in range(1000**2):
        logbook.warn("Hello, World: " + str(i))

if __name__ == '__main__':
    try:
        main()
    finally:
        handler.close()

「対策1」:

$ time python thread_log.py

real    0m58.131s
user    0m54.064s
sys     0m3.913s

「対策2」:

$ time python gzip_log.py

real    0m34.492s
user    0m37.763s
sys     0m0.122s

スレッド版に比べて処理速度の面でも大幅に効率的な事がわかります。もちろん gzip -9 しているので、ログファイルのサイズも大幅に圧縮できています。

対策3: カーネルパラメータチューニング

iowait 対策として、 write がブロックする条件をカーネルパラメータで調整することもできます。

特に重要なのが vm.dirty_ratio という値で、まだディスクに書き込んでない "dirty" なバッファの上限を、メインメモリに対するパーセント値で指定します。書き込みが済んでないデータの量がこの値に到達すると write() がブロックされるようになります。

この値を大きくすると、「時々詰まるけど全体としてはまだディスク書き込み性能に十分な余裕がある」という条件で iowait を消すことができるかもしれません。 一方で、本当に書き込み性能が足りなくなったときに、こまめに短時間詰まっていたのが、低頻度でも致命的に長時間詰まるようになる可能性もあります。 ディスク性能を把握していてまだ余裕があると解っているときに少しずつ増やすか、ちゃんと本番環境と同じスペックの負荷試験環境を用意して想定する上限の負荷を掛けながらチューニングしましょう。

ただし、このチューニングは、負荷試験していたときに思いつかなかったので今回は実施していません。思いつかなかった事が悔しかったのでここで紹介だけしておきました。

対策4: スケールアウト/スケールアップ

問題を把握して真っ先に行ったのが、サーバー台数を増やして数で解決することでした。その時点で現象は軽減されたのですが、解決したわけではなく、特にEBSのレイテンシが悪い一部のインスタンスでまだ問題になっていました。

利用していた EBS が Magnetic だったので SSD にすることもできましたが、今回はゲームの特性上エフェメラルディスクが利用可能だったので、SSDのエフェメラルディスクを利用するようにしました。

アプリケーション側で多少の iowait があっても問題ないようにした上で、ハードウェア側も(コスト的に許されるなら) iowait が無くなるまでスペックアップすることで、安心してサービスすることができます。


@methane
songofacandy at 20:02│Comments(0)TrackBack(0)

トラックバックURL

この記事にコメントする

名前:
URL:
  情報を記憶: 評価: 顔   
 
 
 
Blog内検索
Archives
このブログについて
DSASとは、KLab が構築し運用しているコンテンツサービス用のLinuxベースのインフラです。現在5ヶ所のデータセンタにて構築し、運用していますが、我々はDSASをより使いやすく、より安全に、そしてより省力で運用できることを目指して、日々改良に勤しんでいます。
このブログでは、そんな DSAS で使っている技術の紹介や、実験してみた結果の報告、トラブルに巻き込まれた時の経験談など、広く深く、色々な話題を織りまぜて紹介していきたいと思います。
最新コメント