KLabGames Tech Blog

KLabは、多くのスマートフォン向けゲームを開発・提供しています。 スマートフォン向けゲームの開発と運用は、Webソーシャルゲームと比べて格段に複雑で、またコンシューマゲーム開発とも異なったノウハウが求められる領域もあります。 このブログでは、KLabのゲーム開発・運用の中で培われた様々な技術や挑戦とそのノウハウについて、広く紹介していきます。

カテゴリ: サーバーサイド

はじめに

こんにちは、@tsukimiyaです。シンボリックリンク切り換えによるホットデプロイ、したいですか?シンボリックリンク切り換えによるデプロイはアトミックなデプロイを低コストで実現する手段です。最近はDeployerやCapistranoなどシンボリックリンク切り換えによるデプロイ作業を簡単に行うためのツールも充実し、自分で頑張ってシェルスクリプトを書かずとも低コストでシンボリックリンク切り換えデプロイを行う事が可能です。

ただ、PHPでのシンボリックリンクの切り換えによるデプロイについてネット上を見ていると「nginx+php-fpm環境でOPcacheを有効にしているとシンボリックリンクを切り換えてもキャッシュされている切り換える前のコードが実行され続ける」という情報がいくつか見つかります。OPcacheが原因となるならApache+mod_php環境下でも同様の問題は発生しそうですが、トラブルに遭遇しているのはnginx-php-fpm環境の人ばかりです。実際、自分は普段Apache + mod_php環境をよく使っているのですが実行するコードがいつまでも更新されない、というトラブルには遭遇していないように思います。

今回はnginx + php-fpm, Apache + mod_phpそれぞれの環境に対し検証コードを実行し、問題の確認・原因の切り分けをしてみました。

準備

実験環境は以下のような構成で準備しました。

ディレクトリ構成

.
|-- 1
|   |-- index.php
|   `-- lib
|       `-- user.php
|-- 2
|   |-- index.php
|   `-- lib
|       `-- user.php
`-- docroot -> 1

プログラム

  • index.php

<?php
require_once(dirname(__FILE__).'/lib/user.php');
echo "index(1):" . __FILE__ . "<br>";
foo();
  • lib/user.php

<?php
function foo()
{
	echo "lib(1):" . __FILE__ . "<br>";
}

ディレクトリ1, ディレクトリ2がソースコードが存在するディレクトリの実体で、docrootがドキュメントルートに設定するディレクトリ1, またはディレクトリ2へのシンボリックリンクになります。
このコードをnginx + php-fpm環境とapache+mod_php環境でシンボリックリンクを書き換えながらそれぞれ実行してみます。

PHPにはOPcacheの他にもrealpath cacheという仕組みがあり、開いたファイルの実パスを一定時間(php.iniのrealpath_cache_ttlに設定した秒数の間。標準は120秒。)キャッシュするという仕組みがあります。コード中に存在する__FILE__は実行しているスクリプト自身のパスが入るPHPが自動的に定義する定数ですが、これがRealpath cacheの影響を受ける事を考え、念のためディレクトリ1のコードには(1)、ディレクトリ2のコードには(2)と直接記述しました。
realpath cacheとシンボリックリンク切り換えリリース時にrealpath cacheが引き起こす問題について興味のある方は「PHPにおけるシンボリックリンクを使ったデプロイの危険性について(「realpath_cache」和訳)」で詳しく説明されているので、興味のある方はこちらもご覧ください。

検証

検証はphp-fpm, mod_phpそれぞれの環境に対して以下の手順で進めました。

1. ディレクトリ1に対してシンボリックリンクを張りindex.phpを実行しOPcacheにキャッシュさせる

まずはindex.phpを実行しOPcacheにキャッシュさせます。この時点ではディレクトリ1に対してシンボリックリンクを張り、そのまま実行しているだけなので出力は以下のようになり結果に差違は見られません。

nginx+php-fpm Apache + mod_php
出力 index(1):/var/www/1/index.php
lib(1):/var/www/1/lib/user.php
index(1):/var/www/1/index.php
lib(1):/var/www/1/lib/user.php

2. docrootへのシンボリックリンクを2に張り替えindex.phpを実行する

シンボリックリンクを張り替え、すぐにindex.phpを実行した結果です。

nginx+php-fpm Apache + mod_php
出力 index(1):/var/www/1/index.php
lib(1):/var/www/1/lib/user.php
index(1):/var/www/1/index.php
lib(1):/var/www/1/lib/user.php

この時点ではどちらの環境でも 1/index.php が実行されています。これはrealpath cacheが「docroot/index.php => 1/index.php」という情報をキャッシュしているから、と考えられます。

3. 120秒経過した後、もう一度index.phpを実行する

今回調べたいのはOPcacheがシンボリックリンク切り換えに与える影響なので、PHP本体が作成したrealpath cacheの有効期限が切れるのを待ちます。今回はphp.iniを編集せずに検証しているので、realpath_cache_ttlの標準設定である120秒が経過するのを待ちもう一度実行します。

nginx+php-fpm Apache + mod_php
出力 index(1):/var/www/1/index.php
lib(1):/var/www/1/lib/user.php
index(2):/var/www/2/index.php
lib(2):/var/www/2/lib/user.php

Apache + mod_php環境では 2/index.php が実行されました。対して、nginx + php-fpm環境は 1/index.php のままです。念のために時間をあけてもう一度実行したりもしましたが、nginx + php-fpm環境では 1/index.php が実行され続けました。
一体何が起きているのでしょうか?

古いコードが実行され続ける原因

OPcacheがキャッシュしているのはPHPのopcodeだけではありません。realpath cacheの情報も一部OPcacheが管理する共有メモリ上に保存します。この「realpath cacheのキャッシュ」はphp-fpm, mod_phpどちらの環境でも作られるものですが、このキャッシュが存在している状態でrealpath cacheの有効期限が切れた場合の挙動がphp-fpmとmod_phpで違うのです。Apache + mod_phpの場合、realpath cacheの有効期限が切れるとOPcacheが保持しているrealpath cacheのキャッシュも作り直されるのですが、nginx + php-fpm環境の場合realpath cacheの有効期限が切れてもOPcacheは新しく作られたrealpath cacheを無視して古いrealpath cacheの情報を保持し続けます。実際、3)を行った際にrealpath_cache_get()関数を使いrealpath cacheが保持している内容を見ると
「docroot/index.php => 1/index.phpというキャッシュはexpireされ、docroot/index.php => 2/index.php というキャッシュが作られているにも関わらず 1/index.php が実行され続けている」
という状態を確認することが出来ます。

OPcacheのキャッシュをクリアする

今回の検証でOPcacheがシンボリックリンク張り替え前のrealpath cacheをOPcacheがキャッシュし、nginx + php-fpm環境の場合古いキャッシュを保持し続ける事でシンボリックリンクを切り換えても古いコードが実行され続ける可能性があることがわかりました。原因はOPcacheがキャッシュしているrealpath cacheなのでそのキャッシュを適切にクリアする事が出来ればシンボリックリンクを張り替えた後のコードが実行できるはずです。

OPcacheのキャッシュは「プロセスを再起動する」か「opcache_reset()関数を呼ぶ」ことでクリアすることが出来ます。このうち、プロセスの再起動はダウンタイムが発生する代わりにopcache, realpath cache共に消えるためダウンタイムの発生が許容出来るなら最も確実な方法です。
では、opcache_reset()関数はどうでしょうか。

実は、PHP7.0以降なら一定の解決策になりえます。PHP7.0以降のopcache_reset()はOPcacheのキャッシュ内容をクリアするのとあわせて、全てのプロセスPHP本体側のrealpath cacheをクリアするので、不整合が発生することはありません。

一方でPHP5.6までのopcache_reset()関数はPHP本体側のrealpath cacheにはノータッチでした。よって以下のような問題が引き起こされます。

  1. 新しいコードをデプロイしシンボリックリンクを切り換え
  2. opcache_reset()実行
  3. realpath cacheがexpireする前にプログラムが実行される
  4. OPcacheが古いrealpath cacheをキャッシュしてしまう
  5. nginx + php-fpm環境だと以前のコードが実行され続ける

この問題を解決するには「realpath cacheがexpireされてからopcache_reset()関数を実行する」事になり、現実的ではありません。

opcache_reset()を実行するまでは以前のコードが実行される可能性があり完全な解決策とは言えませんがロードバランサー切り換えほど大げさな仕組みを用意しづらい環境で、かつPHP7以降を使っているならopcache_reset()を使う事を考えても良いかもしれません。
ただ、この方法だとopcache_reset()を叩くためのPHPコードを用意しなければならず、本番環境に適応する場合opcache_reset()を叩くためのPHPコードはローカルアクセスしか出来なくする、と一手間付け加える事が必要になります。そこで検討したいのが次の方法です。

Webサーバにシンボリックリンクからrealpathへの解決を任せる

nginxを使用している場合、nginxにrealpathの解決を任せる事が可能です。
nginxの設定で

fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;

としている箇所を

fastcgi_param SCRIPT_FILENAME $realpath_root$fastcgi_script_name;
fastcgi_param DOCUMENT_ROOT $realpath_root;

に変更します。こうすることでシンボリックリンクからrealpathへの解決がnginxで行われ、PHPは常にrealpathで動作する事になりシンボリックリンクを切り換えた際に発生するOPcacheやrealpath cacheによる問題は起こらなくなります。この方法ならopcache_reset()を使用する方法とは違い管理用のプログラムを別に用意することもないですし、アトミックなデプロイも完全な形で行えます。

おわりに

OPcacheを有効にしているnginx + php-fpm環境でシンボリックリンク切り換えによるデプロイを行うとopcodeが更新されず古いコードが実行され続けるらしい、という漠然とした情報から興味を持ち調べてみたのですが、実際にnginx + php-fpm環境では古いコードが実行され続ける事が確認出来ました。自分としては実行している環境がOPcacheの挙動に影響を与えるとは考えていなかったため、実際に挙動が変わる事が確認出来たのは面白い発見でした。
また、opcache_reset()によってキャッシュをクリアすれば解決する、という記事も何件か見たのですがopcache_reset()はPHPのバージョンにより挙動が違いPHP7.0以降なら一定の解決策になり得ると言う事がわかったのも自分としては新しい発見でした。

  • OPcacheを有効にしているnginx + php-fpm環境ではOPcacheが原因で古いコードが実行され続ける可能性があること
  • その環境でもnginxにrealpathの解決を任せたりPHP7.0以降のopcache_reset()関数を使えば便利さを損なわずデプロイツールの恩恵を得られること

が伝われば幸いです。

この文書は@julienPauliさんによる記事「realpath_cache」の日本語翻訳です。元々は@gilbiteさんがKLab社内向けに翻訳したものでしたが、日本語では見たことがない指摘を含んでおり今でも有用だと考えたため、@julienPauliさんの了解を取った上で@hnwが修正・追記して公開するものです。

はじめに

PHP に realpath_cache_get(), realpath_cache_size() という関数があることをご存じでしょうか? また、php.ini に realpath_cache から始まる設定項目があることは?

realpath cache は知っておきたい極めて重要な概念です。 特に、コードのデプロイ時にシンボリックリンクを取り扱う場合は知っておくべきでしょう。 この仕組みはサーバの性能向上およびIOの削減を実現するもので、PHP 5.1 で導入されました。 ちょうど PHP 界隈にフレームワークが現れ始めた時期ですね。

stat システムコールの復習

あなたのシステムがどうやって動いているのか、重々ご承知とは思いますが、いったん整理しましょう。 特定のパス が指定された場合に、カーネルやファイルシステムは実際のところ何が指定されたのかを知る必要があります。 (Unixでいうところの)ファイルにアクセスしようとしてパスを指定するときは、必ずあなた自身なり、ライブラリなり、カーネルなりがそのパスを解決する必要があります。 ここでいうパスの解決とは、要はそれがファイルなのか、ディレクトリなのか、はたまたリンクなのか、という情報を得る事です。

パスの解決は、OSにそのファイルの種類を問い合わせることで行われます。 ファイルがシンボリックリンクだった場合は、さらにリンク先のファイルの種類を問い合わせることになります。 "../hey/./you/../foobar" のような相対パスの場合には、まずフルパスに直し、そのフルパスのパス解決を行います(Unixでいうファイルは、すべての種類の実ファイル、ディレクトリ、リンクのことを指します)。

通常、相対パスについては、C の realpath() 関数が呼ばれます。 そして、この関数は、stat() システムコールを呼びます

stat() は重い処理です。 システムコールですからカーネルトラップやコンテキストスイッチを発生させますし、ほぼ確実にディスクに対してメタデータを問い合わせます。 カーネルの stat() のソース http://lxr.free-electrons.com/source/fs/stat.c#L190 を追ってみると、予想通りファイルシステムへの問い合わせ (inode->getattr()) につながっていますね。 通常、カーネルは buffer cache を使用するためディスクへの問い合わせの影響はかなり小さいのですが、高負荷なサーバでは欲しい情報がbuffer cacheに乗っていないかもしれません。 その結果、できれば発生させたくないはずの IO が発生してしまうことになります。

PHP がやっていること

PHP のプロジェクトでは大量のファイルを使用しますよね。 昨今は大量のクラスを使用するので、大量のファイルが存在することになります(1ファイルに1クラスだと仮定しています)。 ですから、autoload していようとなかろうと、大量のファイルを include し、読み込み、カーネルに stat 情報を問い合わせる必要があります。 そんなわけで、PHPからファイルアクセスするたびにパスの解決、リンクの解決、またファイルの情報の取得が行われます。 これらは全て stat() システムコールを使用します。 そこで、stat() システムコールの結果は realpath cache と呼ばれる領域にキャッシュされています。 実はPHPの他にも多くのソフトウェアがstatをキャッシュしています。コードを眺めてみれば気づきますよ ;-)

システムコールの結果をキャッシュするといっても、PHP がキャッシュするのはパス解決された結果であるところのrealpathだけです。(オーナーや、パーミション、各種日時といった)その他の情報はrealpath cacheではキャッシュされません。ただし、PHPには最後のstatシステムコール1件をキャッシュする仕組みがあり、そちらではその他の情報もキャッシュされます。

例によって、ソースコードを確認してみると良さそうですね。 PHP でファイルへのアクセスが発生すると、php_resolve_path() が使用されます。 この関数はすぐに tsrm_realpath() を呼びますが、 これも virtual_file_ex() を呼び、 最終的に tsrm_realpath_r() が呼ばれます。

ここからが面白いところです。realpath_cache_find() などの関数が呼ばれると、指定されたパスに対してstat 情報が過去に問い合わせされて既にキャッシュされているかどうか、realpath cacheの連想配列を検索します。

この連想配列の要素には構造体 realpath_cache_bucket が使用されており、多くの情報がカプセル化されています:

typedef struct _realpath_cache_bucket {
    zend_ulong                    key;
    char                          *path;
    char                          *realpath;
    struct _realpath_cache_bucket *next;
    time_t                         expires;
    int                            path_len;
    int                            realpath_len;
    int                            is_dir;
#ifdef ZEND_WIN32
    unsigned char                  is_rvalid;
    unsigned char                  is_readable;
    unsigned char                  is_wvalid;
    unsigned char                  is_writable;
#endif
} realpath_cache_bucket;

この bucket が見つからなかった場合は、lstat() のプロキシである php_sys_lstat() が呼ばれ、ファイルシステムへの問い合わせを行います。 そして、問い合わせ結果を含むbucketが realpath cache へと保存されます。

PHP 設定とそのカスタマイズ

さて、PHP の realpath cache で抑えておくべきことがいくつかあります。まずは INI の設定から。:

マニュアルが警告している通り、そう頻繁にファイル変更が起こらないようなサーバ(プロダクション環境)の場合は、TTL を大きくしておくべきでしょう。 また、デフォルトの size はとんでもなく小さいですね。Symfony2 のようなフレームワークを使っているのであれば、16K は1リクエストで埋まってしまいます。 realpath_cache_get() を監視すれば、16K の制限にすぐ引っかかってしまう様子が見て取れるでしょう。 512K とか、なんなら1Mにした方が良いでしょう。 realpath cache が埋まるということは、他のエントリのための余地が無くなっている状態ですから、キャッシュミスが原因でstat()が乱発され、カーネルにストレスを与え続けてしまいます。 この size を理論的に導出するのは難しいのですが、ソースのここを見る限り、1エントリにつき、sizeof(realpath_cache_bucket) + 解決されたパスの総文字数 + 1 となっています。 自分の環境(LP64)では、sizeof(realpath_cache_bucket) = 56 バイトでした。

もう一つ落とし穴があります。PHP は出会った全てのパスを解決しようとしますが、その際に細かくパーツ分けして、1つずつパス解決していきます。 "/home/julien/www/fooproject/app/web/entry.php" にアクセスしたとしますね。 そうすると、まず、最少単位に分解して "/home" の解決をして 1 エントリとしてキャッシュに放り込む、続いて "/home/julien"、"/home/julien/www"とやっていきます。 どういうことでしょうか?理由の一つは、ディレクトリの全レベルのアクセスを確認するのに使うためです。 次に、多くの PHP ユーザはパスを組み立てるのに文字列連結する傾向があるので、あるパスの一部をPHPが確認済みかもしれません。 その場合、realpath cache に問い合わせればユーザーがアクセス可能かどうか判断することができます。 キャッシュへの問い合わせは非常に軽いですからね。 詳細の処理はtsrm_realpath_r() のソースコードに記述されています。 これは全てのサブパスについて呼び出される再帰関数です。

これまで見てきた通り、キャッシュはあった方がいいですよね!

新規にデプロイしてウェブサイトを公開する前に、URL をいくつか叩いてキャッシュを準備しておくのも重要です。 これはOPcode キャッシュだけではなくて、realpath cache、ひいてはカーネルのページキャッシュを準備するという事にもなります。

さて、realpath cacheはどうクリアするのでしょうか?この関数はPHP上で隠されています。realpath_cache_clear() だと思いましたか?残念ながらそんな関数は存在しません :-) clearstatcache(true) なのです。この true が非常に大事です。このパラメータ名は$clear_realpath_cacheで、言うまでもなく我々が探していたものです。

では、例を。

<?php
$f = @file_get_contents('/tmp/bar.php');

echo "hello";

var_dump(realpath_cache_get());

この場合、次のような結果が得られます。:

hello
array(5) {
  ["/home/julien.pauli/www/realpath_example.php"]=>
  array(4) {
    ["key"]=>
    float(1.7251638834424E+19)
    ["is_dir"]=>
    bool(false)
    ["realpath"]=>
    string(43) "/home/julien.pauli/www/realpath_example.php"
    ["expires"]=>
    int(1404137986)
  }
  ["/home"]=>
  array(4) {
    ["key"]=>
    int(4353355791257440477)
    ["is_dir"]=>
    bool(true)
    ["realpath"]=>
    string(5) "/home"
    ["expires"]=>
    int(1404137986)
  }
  ["/home/julien.pauli"]=>
  array(4) {
    ["key"]=>
    int(159282770203332178)
    ["is_dir"]=>
    bool(true)
    ["realpath"]=>
    string(18) "/home/julien.pauli"
    ["expires"]=>
    int(1404137986)
  }
  ["/tmp"]=>
  array(4) {
    ["key"]=>
    float(1.6709564980243E+19)
    ["is_dir"]=>
    bool(true)
    ["realpath"]=>
    string(4) "/tmp"
    ["expires"]=>
    int(1404137986)
  }
  ["/home/julien.pauli/www"]=>
  array(4) {
    ["key"]=>
    int(5178407966190555102)
    ["is_dir"]=>
    bool(true)
    ["realpath"]=>
    string(22) "/home/julien.pauli/www"
    ["expires"]=>
    int(1404137986)

例示のPHPファイルのフルパスがパーツごとに解決されているのがわかると思います。 実は/tmp/bar.phpは存在していないので、当然ながらこのエントリーはキャッシュにはありません。 しかし、/tmpまでは解決されていることがわかります。つまり /tmp へはアクセス可能であることがわかるため、 これ以後の/tmp以下のパス解決は、最初の1回より安上がりになります。

realpath_cache_get() が返す連想配列には、キャッシュ失効時刻("expires")など重要な情報が入っていますね。 これはrealpath_cache_ttl の設定値とファイルへの最終アクセス日時から計算されています。 key は、解決されたパスのハッシュ値で、FNV hash の一種が使われています。 ですが、これは内部的な情報であって必要な情報ではありません(この値はシステムの整数のサイズに応じてinteger もしくは float になります)。

ここでclearstatcache(true) を呼ぶとrealpath cacheの連想配列がリセットされ、以前にキャッシュされていたファイルであっても新しいファイルアクセスとして PHP に stat() を強制させることになります。

OPcode cache の場合

さらに別の落とし穴を紹介しましょう。

realpath cacheは、プロセスごとに存在するものであって、共有メモリで共有されるものではない

ですから、キャッシュの失効や変更、手動での消去などについては、プロセスプール内の全てのプロセス で行われる必要があるのです(訳注:全プロセス横断でのrealpath cache消去機能は提供されていないため、非現実的だと考えるべきでしょう)。 opcode キャッシュ拡張を使っている場合にコードデプロイが失敗するのはこれが主な理由です。 デプロイ時にはシンボリックリンクの切り替えをすると思います。例えば /www/deploy-a から /www/deploy-b のように。 ここで忘れがちなのが、opcode キャッシュ拡張は(少なくとも OPCache と APC については)、PHPの内部的な realpath cache を信頼しているということです。 つまり、opcode キャッシュ拡張はシンボリックリンク先の変更があったことに気づきません。 さらに悪いことに、realpath cacheの全エントリが徐々に失効していくにつれ、徐々にリンク先の変更に気づいていくわけです。 どうなるかは言わんでも分かりますな?

デプロイ時にこの残念なメカニズムの発生を防ぐ一番の解決策は、完全に新しいPHPワーカープールを準備しておくことです。 fastCGI handler でその新しいプールにロードバランスさせ、古いプールはワーカーが全部仕事をやり終えたら放棄してしまえばよいのです。

この方法だと良い点がたくさんあります。 デプロイA が メモリプールA で動いて、デプロイB が メモリプールB で動く。 以上。 2つのデプロイ間で完全にメモリイメージの分離を行い、なんのメモリ共有もさせない。 realpath cacheも、opcode cache も、何もかもが新しくなるわけです。 FastCGI プールのロードバランスは、少なくとも Lighthttpd と Nginx では使えます :) 私もプロダクション環境で実践していますが、手堅いですよ!

終わりに

realpath cacheについて何か書いてくれと依頼されたのは、多分、皆がツラい経験をしたことがあるからだと思います(それも、おそらくコードのデプロイ時に)。 ということで、その仕組と、存在意義や設定の変更の必要性とその仕方を書きました。他に何かあるかな?

翻訳者による補足

PHPプロジェクトでシンボリックリンク切り替えによるデプロイ(特にホットデプロイ)を行っている場合に、OPcacheとの組み合わせで何故か新しいファイルに切り替わらない、という事件があちこちで起きているのではないでしょうか。その原因の一つと、解決策を示した文章を紹介しました。

本稿で指摘されている、シンボリックリンクによるデプロイとrealpath cacheとの相性の悪さは非常に悩ましい問題です。元の記事ではOPcacheとの組み合わせで問題が起きるように読めるかもしれませんが、実はOPcache無しでもrealpath cacheが古いシンボリックリンク先を返してしまうことで同様の事故が起こる可能性があります。

多くのPHPプロジェクトではrealpath_cache_sizeの値が小さすぎて本稿の問題そのものは起きないかもしれません。その場合でも、OPcacheが提供している全プロセス共有のrealpath cacheという、本稿で触れられていない落とし穴があります。実はこちらの方がトラブル事例としては多い可能性もありそうです。

本稿で提案されているプロセスプールを新旧2個用意するという解決策は完璧ではあるものの、小規模案件では非現実的なこともあるでしょう。 元記事の筆者の@julienPauliさんはSensioLabsの社員でもあります。同社はSymfonyの開発元として有名で、大規模案件に取り組んでいることで知られていますから、この解決策で特に問題はないということだと思われます。

(11/1 08:45 追記)一方で、プロセスプールを2個用意するという提案は安全側に倒しすぎだという見方もできます。というのも、シンボリックリンクを利用したデプロイを行っていても本稿で指摘した問題が露呈しない状況もあるのです。詳細はまた別エントリでお伝えすることになると思いますが、昨今のフレームワークを使った開発であれば問題が起きない環境の方が多数派だろうと予想しています。ですから、今うまく動いているプロジェクトのデプロイプロセスをわざわざ変更する必要は無いでしょう。

こんにちは, @mecha_g3 です.

ISUCON6に「この技術部には問題がある!」チームとして出場し, 優勝しました.
メンバーは まとめ役の @methane, インフラ屋の @kizkoh, 僕がアプリ改造を担当しました.

他のメンバー参加記事:

予選とその反省

ISUCON6予選をトップ通過しました

余裕を持って優雅に戦えたとか書いてありますが, 僕は全然余裕がなく, 準備したツールが中々動かなかったり, git 操作のミスで変更が反映されてなかったり, DBコネクションを食いつぶす変なバグを埋め込んでしまったりで足を引っ張りまくりでした.

その反省もあって, 本選用にAWSの開発環境を用意し, 作業に必要なツールやエディタの設定は全て済ませておきました.
またこの開発環境では, ログの収集やアプリのデプロイ, ベンチマーク時のプロファイルの結果をhtml形式でレポートするスクリプト等を作っておきました.

さらに, 予めスタートダッシュチェックリストを作っておき, 問題公開後にしかできないけど必ず必要な作業の一覧を作り, 誰がやるか予め決めておきました.

この開発環境とスタートダッシュチェックリストのおかげで, 本選時にアプリの改造に集中することができました.

例えば

  • ~/deploy で競技サーバにアプリのデプロイ
  • ~/restart で競技サーバのアプリやnginx, MySQLの再起動.
  • ~/applog で競技サーバ上のアプリのログをtail -f
  • ~/make_report ベンチマーク後, 競技サーバ上のアプリのログを収集してレポートのhtmlを出力してslackに通知

これらを Makefile から呼び出すことで, 競技中に vim の中に閉じこもることができます.
問題に合わせて微妙に変更しないといけない所も, インフラ担当の @kizkoh が良い感じにメンテしてくれました.

本選

前半戦

スタートダッシュチェックリストに書いておいた事を淡々と進めました. 競技が始まると全然頭が回らなくなるので作っておいて本当に良かった.

僕は初期状態のアプリを git 管理してビルドが通るようにし, デプロイスクリプトを修正したり, 8080番ポートでLISTENするようにしたり, 予め用意しておいたプロファイル用のライブラリを挿入したりなどを行いました.

ISUCON のアプリには毎回 /initialize という, ベンチマーク前にデータセットを初期化するリクエストが存在します.
これをトリガにして nginx のログをローテートし, 1分間(ベンチマーク時間) pprofの記録, dstat, pidstat を裏で動かすスクリプトを事前に準備していました.
が, 本選の問題には /initialize は存在せず(やられた), アプリケーション側からベンチの開始を検出するのが難しかったので, ベンチマークをかける頃に /startprofile というパスを手動で叩くようにしました.

Webサーバのログを見ると UA に benchmarker というような文字があったのでこれを使うかも考えましたが, 意図せぬタイミングで暴発すると面倒なのでやめました.

作戦会議

お弁当を食べながらアプリを触ったり, 作戦会議を行いました.
ここまでスタートダッシュに集中していたのでアプリのソースは全然読んでませんでした.

スタートダッシュ中にログの集計やアプリの構成などを理解していた @methane からアプリの構成や, 現状考えている方針を共有してもらいました.

Server-Sent Events は全く触ったことがなかったけど, テキストベースのプロトコルだと分かった後は簡単でした.
svgは業務外で何度か触ったことがあり, xml形式だということは知っていたので怖くはなかったです.

リアルタイムのお絵かきサービスだけど, やることはテキストの共有. つまりチャットのような物.
普段業務でやっている事と大差ないよね, 多分go言語有利な問題だし, 実力出せれば勝てる.

お絵かき部分の共有をとにかく高速化しよう.
内容の変更をDBにポーリングしている構造になっている所を直せば劇的にスコアが上がるはず.
描いた内容は他のクライアントに2秒以内に反映されていれば良いので, 急いで返す必要はなく, ある程度バッファしてまとめて返すほうが効率いいよね.
という会話をしました.

インフラ方面では, dockerを潰し, node.jsをフロントから剥がし, nginxをフロントに置くなど大規模な構成変更を決めていました.

中盤戦

オンメモリ作戦

DBに毎回問い合わせている部分をなくせば良いので, オンメモリ作戦を実施しました.
起動時にDBの内容を全て SELECT しメモリ上に乗せ, 変更された内容は DB に保存しつつオンメモリの内容も更新します.
最新の情報はメモリ上にあるので, DBへの問い合わせをなくすことができます.

全部と書いていますが, ここで行ったのは room, strokes, points が対象です.

最初は, 最終的にアプリをroomで水平分散するかもしれないからそこを意識しつつオンメモリ化を考えていて手が中々動きませんでした.
難しいので1プロセスで動く前提で作ります! と割り切ってからはサクサクと作業が進みました. 最終的にアプリは1プロセスだったので結果論ですが正解でした.

具体的には以下のようなコードを書いていました.

type RoomRepo struct {
    sync.Mutex
    Rooms map[int64]*Room
}

func NewRoomRepo() *RoomRepo {
    return &RoomRepo{
        Rooms: map[int64]*Room{},
    }
}

func (r *RoomRepo) Init() {
    log.Println("room repo init start")
    r.Lock()
    defer r.Unlock()

    rooms := []Room{}
    err := dbx.Select(&rooms, "SELECT `id`, `name`, `canvas_width`, `canvas_height`, `created_at` FROM `rooms` ORDER BY `id` ASC")
    need(err)

    for i, _ := range rooms {
        strokes := []Stroke{}
        err := dbx.Select(&strokes, "SELECT `id`, `room_id`, `width`, `red`, `green`, `blue`, `alpha`, `created_at` FROM `strokes` WHERE `room_id` = ? ORDER BY `id` ASC", rooms[i].ID)
        need(err)

        var owner_id int64
        err = dbx.QueryRow("SELECT token_id FROM `room_owners` WHERE `room_id` = ?", rooms[i].ID).Scan(&owner_id)
        need(err)

        for j, s := range strokes {
            ps := []Point{}
            dbx.Select(&ps, "SELECT `id`, `stroke_id`, `x`, `y` FROM `points` WHERE `stroke_id` = ? ORDER BY `id` ASC", s.ID)
            strokes[j].Points = ps
        }

        rooms[i].ownerID = owner_id
        rooms[i].Strokes = strokes
        rooms[i].watchers = map[int64]time.Time{}
        r.Rooms[rooms[i].ID] = &rooms[i]
    }
    log.Println("room repo init end")
}

func (r *RoomRepo) Get(ID int64) (*Room, bool) {
    r.Lock()
    defer r.Unlock()

    room, ok := r.Rooms[ID]
    return room, ok
}

...

オンメモリ作戦のデバッグ

Go での開発はコンパイルエラーでしょうもないミスはすぐ分かるし, vim の QuickFix でエラー箇所に簡単にジャンプできるのでIDEで開発しているような気分になります.
競技時間中は頭が全然回らず, 焦って明らかに変なコードを書いてしまいがちですがかなり助けられました.

コンパイルが通った後は, 実行時にすぐ分かるエラーを数か所直しました.
ブラウザで動作確認してみると, 全ルームidが同じルームを参照してしまうバグが発生していましたが, forループの変数のスコープのあるある問題だなとすぐ気づき修正できました.

この頃にはインフラ担当の構成変更も終わり, HTTP2を喋っていて 10000点 以上でるようになっていました(すごい).
ここにオンメモリ作戦の改造を入れたアプリをデプロイし, ベンチマークをかけてみると一発でPASSし 23428点.

svg生成のGo移植

オンメモリ作戦が一段落したところで, @methane が node.js で動いていた /img/* へのリクエストの svg 出力部分をgoで出力する関数ができたので試したいという.
投入してみると, 空の svg が出力されていて動作せず. デバッグを任せられたのでとりあえず printデバッグで関数が呼ばれているかなどを確認しました.

DBから引いた状態の room には strokes は空なので, 空の svg が出力されていましたというだけでした. オンメモリ化とつなぎ込めば解決です.

また, 前回ベンチマークの警告からnginxの設定ミスがわかり, それを修正も入っており 39101点.

svg生成結果のキャッシュ

ベンチマーク時のプロファイルを見ていると, svg 生成部分がアプリ全体のうち 64.31% と中々重そうでした.
ここをなんとかキャッシュできると, 他チームに差をつけれそうです.

Strokeは内容は, アプリケーションの性質から, 追記のみであることがわかりました.
つまり, 1stroke毎に <polyline> ... </polyline> が1行増えるだけで, 1度書いた部分が変更されることはありません.

閉じタグを含めない状態の svg を Room 毎にキャッシュしておき, Stroke が増える度に1行ずつ追記します.
/img/* へリクエストが来た際は, キャッシュしている svg を出力し, 最後に </svg> を追加するだけで, 何度も同じ svg を生成しなくてすみます. あたまいい!

具体的には以下のようなコード.

room.svgInit が初回レンダリング済みかどうかのフラグ. 初回 svg 出力時に svgBuf を作ります.
Stroke が追加された場合は 同様の Fprintf で svgBuf に追記します.

func renderRoomImage(w io.Writer, room *Room) {
    room.svgMtx.Lock()

    if !room.svgInit {
        buf := bytes.NewBuffer(make([]byte, 0, 1024))

        fmt.Fprintf(buf,
            `<?xml version="1.0" standalone="no"?><!DOCTYPE svg PUBLIC "-//W3C//DTD SVG 1.1//EN" "http://www.w3.org/Graphics/SVG/1.1/DTD/svg11.dtd"><svg xmlns="http://www.w3.org/2000/svg" version="1.1" baseProfile="full" width="%d" height="%d" style="width:%dpx;height:%dpx;background-color:white;" viewBox="0 0 %d %d">`,
            room.CanvasWidth, room.CanvasHeight,
            room.CanvasWidth, room.CanvasHeight,
            room.CanvasWidth, room.CanvasHeight)

        for _, stroke := range room.Strokes {
            fmt.Fprintf(buf,
                `<polyline id="%d" stroke="rgba(%d,%d,%d,%v)" stroke-width="%d" stroke-linecap="round" stroke-linejoin="round" fill="none" points="`,
                stroke.ID, stroke.Red, stroke.Green, stroke.Blue, stroke.Alpha, stroke.Width)
            first := true
            for _, point := range stroke.Points {
                if !first {
                    buf.WriteByte(' ')
                }
                fmt.Fprintf(buf, `%.4f,%.4f`, point.X, point.Y)
                first = false
            }
            buf.WriteString(`"></polyline>`)
        }

        room.svgBuf = buf
        room.svgInit = true
    }

    svg := room.svgBuf.Bytes()
    room.svgMtx.Unlock()

    w.Write(svg)
    w.Write([]byte(`</svg>`))
}


func (r *RoomRepo) AddStroke(roomID int64, stroke Stroke, points []Point) {
    r.Lock()
    defer r.Unlock()

    room, ok := r.Rooms[roomID]
    if !ok {
        log.Println("[warn] no such room")
        return
    }

    stroke.Points = points
    room.Strokes = append(room.Strokes, stroke)

    room.svgMtx.Lock()
    if room.svgInit {
        buf := room.svgBuf
        fmt.Fprintf(buf,
            `<polyline id="%d" stroke="rgba(%d,%d,%d,%v)" stroke-width="%d" stroke-linecap="round" stroke-linejoin="round" fill="none" points="`,
            stroke.ID, stroke.Red, stroke.Green, stroke.Blue, stroke.Alpha, stroke.Width)
        first := true
        for _, point := range stroke.Points {
            if !first {
                buf.WriteByte(' ')
            }
            fmt.Fprintf(buf, `%.4f,%.4f`, point.X, point.Y)
            first = false
        }
        buf.WriteString(`"></polyline>`)
    }
    room.svgMtx.Unlock()
}

これで /img/* のCPU時間が数倍早くなり, 44655点.

終盤戦

@kizkoh は MySQL と node.js を別サーバに移したりなど, 複数台構成に向けての変更を行っていました.
@methane は node.js に文句をいいながら何かをやっていました.

僕は他にチューニングできるところが無いか探し, まだオンメモリ化できていない, /api/rooms をオンメモリ化する作業を行っていました.
ここには全然リクエストが来ていなかったので, 高速化してもスコアは伸びないと思ってましたが, 遅いせいでワークロードが下がりリクエストが来ていないのかもと思い一応着手しました.

インフラの構成変更が最優先だったので, この変更はなかなかベンチをかけれず..

終了30分前には複数台構成が落ち着き, node.js に対する謎の変更も入り, 最高点 83560点 を記録.
このあと /api/rooms のオンメモリ化をデプロイしてみると 13000点 程度に落ちてしまったのでエラーも見ずに巻き戻し.

安全にゴールしようという事で全台再起動試験. 問題なくうまく立ち上がり一安心.
しかし, ベンチをかけてみるとなぜか 55729点. 83560点 と同じ構成のハズなのに..

もう一度ベンチをかけると 59296点. なんだかスコアが不安定である.
会場の他チームがラストスパートをかけた為Azure東日本リージョン全体が重くなったのか, 再起動時にハズレインスタンス引いたのか.

とにかく1分毎に Enqueue を押して, 良いスコアが出るのを祈る... が 55855点 でFINISH.

終了後

ベスト時に比べると 27000点も低いスコアで終わってしまったので不完全燃焼.
ベスト時のスコアなら優勝だったのに! という事にならないかとても不安でした.

練習してきた事はちゃんと発揮できたし, 役割分担も良かった. 後悔は無いね, という感じでドキドキの結果発表.

最初に75000点を超えたということで特別賞を受賞.
その後, 2位の発表でスコアが3万点台だったのを見てガッツポーズ! 優勝を確信しました.

懇親会

初対面の方が多かったですが, 優勝チームということもありたくさん絡んでもらえました.
みなさん個性的で面白い方ばかり, 1日同じ問題に取り組んだ人同士の会話は盛り上がらないはずはなく, 懇親会はあっという間に終わりました.

他にも, 高専プロコンつながりで知っていた沖縄高専の学生チームと話したり, 秋葉さん imosさんの 競プロC++ チームと絡んだりでき, 非常に楽しかったです.

勝って飲む酒の美味しいこと!!!

感想

毎年予選あたりの時期は忙しい事が多く, 練習時間がとれず過去2回予選落ちし, 本選に出場できたのは今回が初めてでした.
今年こそ本選に行くぞ! という気持ちで今年は予選1ヶ月前から練習を開始しました.

ISUCON では, アプリの改造する為の知識はもちろん, HTTPのキャッシュの管理, MySQL や nginx のチューニング, カーネルパラメータのチューニングなど, 上から下まで知識が要求されます.
そもそも存在を知らなければチューニングできませんし, 付け焼き刃の知識では試行錯誤で時間が奪われます.

普段からGoでアプリを書いている人, 普段からインフラをメンテナンスしている人, 幅広い知識があり全体を見て方針を決めれる人 のチーム構成は完璧だったと思います.

優勝賞金は, もうすぐ発表になると予想されている MacBook Pro の新型を買って, ISUCONステッカーを貼ります. これでモチベーションを上げて来年からも優勝目指すぞ!

最後に, ISUCON の練習に業務時間をたくさん使わせて頂きました. 本当に感謝してます. いつか還元するので許してください :)

↑このページのトップヘ