syslogに注意！

2010/03/16

ProDHCPを採用いただいたお客さんのところで、どうしても性能が出ないということで調査を続けていました。仮想環境で動いているとか様々な条件を合わせて動作確認してもなかなか再現ができず、かなり行き詰まった状態だったのですが、昨晩、ほぼこれだろうという問題を見つけました。

syslogです。syslogは、システムのログを記録するための仕組みで、UNIX系では古くから使われています。ログレベルによる管理や出力先の管理など、多機能で便利なのですが、昔から「syslogは遅い」ということは知っていました。単に自分でファイルに書き込むのに比べると圧倒的に遅いですし、あまりに頻繁な書き込みを行うとアプリがハングアップしてしまうことも何度も経験しています。従って、デバッグに必要な詳細なログはファイルに自力で書き込み、syslogには運用・管理面で必要最低限なログのみ記録するというのがルールになっているような感じです。

ProDHCPもお勧めの運用はそのようになっていて、基本的にエラーとアドレスの貸し出しに関する記録のみをsyslogに行うようにしています。今回のお客さんももちろんそうしていたのですが、それでも性能が出なかったのです。が、自社のテスト環境では同じ設定にしてもスイスイ動きます。

実はsyslogには、動作設定ファイルのsyslog.confに、

「
マイナス記号 ``-'' を接頭すると、記録の際のファイルシステムバッファのフラッシュ動作を抑制する。これを用いると、書き込み動作の直後にシステムに障害が発生した場合、情報を失なう可能性があることに注意すること。しかしながらこの機能は特に騒々しくロギングするプログラムを動作させる際のいくらかの性能改善には役に立つ。
」

このような機能があるのでした。標準のsyslogは1行記録するたびにfsync()を使ってファイルシステムへの同期を行うようになっていて、非常に遅いのです。もちろんシステムのログを記録するという役割から、OSがクラッシュしても可能な限りログを残すという目的を考えるとその通りという感じなのですが、それにしても遅いのです。今回のお客さんのDHCP運用では非常に巨大な数のクライアントを管理しているため、必要最低限のログでもかなり頻繁にsyslogに記録されていて、それがI/Oウエイトのために遅くなっていたのでした。CPU負荷としては低いのに、性能が出ないという状態でした。

*.info;mail.none;news.none;authpriv.none;cron.none /var/log/messages
↓
*.info;mail.none;news.none;authpriv.none;cron.none -/var/log/messages

こんな感じに出力先のパスの先頭に'-'を付けるとファイルへの同期を毎回行う処理をやめてくれます。これだけで飛躍的に処理性能が変わるのでした。

たまたまLinuxのディストリビューションによっては標準で'-'がついているものや、高速化されたsyslogを使っているものがあり、自社のテスト環境では問題が出なかったのでした。

アプライアンスであればOSや環境設定まで含めて製品として提供できますが、ソフト販売の場合は、インストールするOSや環境設定の状態によって動作に差が出る点は非常に気を使います。しかし、お客さんの立場としてはソフトで購入したいという希望も確実にあります。ハードウェアは自分で選定したい、ハードウェアの入れ替えも自分で行いたい、仮想環境内に入れたい、などの理由です。我々は少なくともアプリは完全に自作して販売しているので、まださまざまな解析もやりやすい方だと思いますが、ソフト販売は意外とサポートが大変なものなのです。

さて、せっかくなので、実際にfsync()の遅さを確認してみましょう！

「
#include       <stdio.h>

int main()
{
int    i;
FILE *fp;

      fp=fopen("test.out","w");

      for(i=0;i<100000;i++){
            fprintf(fp,"test%d\n",i);
//             fflush(fp);
//             fsync(fileno(fp));
      }

      fclose(fp);

      return(0);
}
」

●fsyncあり
real 0m12.589s
user 0m0.071s
sys 0m0.108s

●fflushあり
real 0m0.254s
user 0m0.037s
sys 0m0.217s

●どちらもなし
real 0m0.038s
user 0m0.034s
sys 0m0.004s

●どちらもあり
3分たっても終わらない・・・
二桁ループを減らして、1000回で
real 0m47.072s
user 0m0.001s
sys 0m0.024s

これは、低水準I/O使うと遅いだろうということで、

「
#include       <stdio.h>
#include       <fcntl.h>
#include       <unistd.h>
#include       <string.h>

int main()
{
int    fd,i;
char buf[512];

      fd=open("test2.out",O_WRONLY|O_CREAT);

      for(i=0;i<1000;i++){
            sprintf(buf,"test%d\n",i);
            write(fd,buf,strlen(buf));
//             fsync(fd);
      }

      close(fd);

      return(0);
}
」

●fsyncあり
real 0m50.453s
user 0m0.001s
sys 0m0.024s

●fsyncなし
real 0m0.002s
user 0m0.002s
sys 0m0.001s

呆れるほどの違い！

ということで、久々に「仕事で」会社に泊まってしまいました。お客さんは気を使ってくださって、「無理しないで、また明日一緒にお願いします。」と言ってくださったのですが、モヤモヤしたまま帰宅しても眠れるはずもなく、ひたすら調査してました。会社宿泊は、飲み会の後に終電がなくなって泊まることは結構あるのですが、仕事では久しぶりです。会社にはちゃんとお泊まりセットが置いてあるのですが、ヘアブラシがないので買ってきました。これでほぼ完璧でしょうか。

ちなみに、寝袋や枕を常備しているメンバーもいますが、私は作業着に着替えて、鞄にタオルを敷いて枕にして、床（カーペットです）に寝ます。。