Redisでログの書き込みがblockを引き起こす

「RedisかわいいよRedis」(by typester)……というほど自分は Redis 期でもないのですが、最近 Redis を使ったサービスの面倒を見ていて時々レスポンスが悪化する現象に出会ったので調べました。

前提

使用しているのは Redis 2.4.16 です。

redis.conf に "save [t] [n]" を定義すると、最後に save をしてから [t]秒間に [n]個以上の key が更新された場合に background で save (=bgsave) が実行されます。

save 60 10000

これだと、60秒間に 10,000 keys です。

bgsave では redisは自分自身のプロセスを fork() し、子プロセス側は自分のメモリに乗っている内容をファイルにすべて書き出します。

この仕組みによって、1プロセス 1スレッドで動作している redis の操作を block することなしに全データのファイルへの書き込みを実現しています。賢いですね。

発生した問題

redisにアクセスしている webアプリケーションのレスポンスタイムが悪化し、数秒 block するような挙動が見られました。この挙動は、bgsave 実行中に発生しています。

原因の特定

仮に redis が持っているデータが 4GB だったとすると、bgsave するときには 4GB まるごとのファイル書き込みが発生します。

親の redis プロセスはファイル書き込みをしないので DISK IO が多くても問題ない……かと思いきや、設定によっては直接ログファイルを書き込むことがあります。

loglevel verbose
logfile /var/log/redis.log

[3886] 05 Dec 14:13:42 - Accepted 127.0.0.1:36837
[3886] 05 Dec 14:13:42 - Client closed connection
[3886] 05 Dec 14:13:43 - Accepted 127.0.0.1:36838
[3886] 05 Dec 14:13:43 - Client closed connection

どうやら bgsave が走って大量の DISK IO が起きているタイミングでログを書き込むとそこで block するらしい、ということを突き止めました。

特定方法

strace で redis のプロセスが発行する syscall を抽出し、以下の Perl script でタイムスタンプが 0.2 秒以上間隔が空いた前後を出力したところ、write() のあとの close() で数秒掛かることがあるのを発見。ちなみにソースを読むと分かりますが、redis.c 内の redisLog() で、ログ出力ごとにファイルを追記モードで fopen(), fprintf(), fclose() しています。

# strace -ttt -p `pgrep redis` 2>&1 | perl timegap.pl

Wed Dec  5 10:10:29 2012 1354669829.089764 write(52, "[2255] 05 Dec 10:10:29 - Client "..., 50) = 50
Wed Dec  5 10:10:34 2012 1354669834.418856 close(52)             = 0
Wed Dec  5 10:11:55 2012 1354669915.735166 write(55, "[2255] 05 Dec 10:11:55 - Accepte"..., 50) = 50
Wed Dec  5 10:11:57 2012 1354669917.761811 close(55)             = 0

#!/usr/bin/env perl
use strict;
my $prev_ts = 0;
my $prev_line = "";
$| = 1;
while (my $line = <>) {
    chomp $line;
    my ($ts, $log) = split / /, $line, 2;
    if ($prev_ts && $ts - $prev_ts > 0.2) {
        printf "%s %s\n", scalar localtime($prev_ts), $prev_line;
        printf "%s %s\n", scalar localtime($ts), $line;
    }
    $prev_ts = $ts;
    $prev_line = $line;
}

対応

loglevel verbose ではクライアントが接続、切断するごとにログに記録されますが、ヘルスチェックのために毎秒接続・切断をしているのでログファイルへの書き込みも毎秒発生していました。

loglevel notice に変更し、ログ出力を抑制したところ bgsave 時にブロックされる現象がなくなりました。

根本的には、redis がログを直接ファイルに出力するのではなく、標準出力経由で multilog に渡す、syslogに投げるなどに変更するのが better でしょうか。神の書がほしいです。

(変更前後のアプリケーションのレスポンスタイム統計)