読者です 読者をやめる 読者になる 読者になる

Web就活日記

愛と夢と人生について書きます

Redisにマルチプロセスで接続する時に気をつけたい事

Redis in Action

Redis in Action

  • 作者: Josiah L. Carlson,Salvatore Sanfilippo
  • 出版社/メーカー: Manning Pubns Co
  • 発売日: 2013/06/25
  • メディア: ペーパーバック
  • クリック: 1回
  • この商品を含むブログを見る

Redis

広告配信やっています@yutakikucです。
Redisの内部処理が1スレッドで受けているようなので、マルチプロセスからRedisに書き込み処理を大量に流した時にどうなるのかを検証してみました。言語はCを、Libraryはhiredisを使います。redis/hiredis はてなブックマーク - redis/hiredis
hiredisを使って単一プロセスで実行した場合と、Apache Moduleにhiredisを組み込んでマルチプロセスの実行状態で検証します。検証機はCentOS6.4です。

hiredis

Redisのinstall、version確認、起動

RedisのVersionは2.4.10です。

$ sudo yum install redis -y

$ redis-server -v
Redis server version 2.4.10 (00000000:0)

$ sudo chkconfig --add redis

$ sudo /etc/init.d/redis start
hiredisのinstallとテストプログラム

hiredisのinstall後に単純にHashをincrbyするプログラムを実行してみます。まずはプロセス内で単純に指定回数incrbyを繰り返します。今回は指定回数を1万としたので、かなり高速に書き込みが完了している事が分かると思います。実行後にはredis-cliで書き込みが出来ているかを確認します。

$ sudo yum install hiredis hiredis-devel -y

$ gcc -I/usr/include/hiredis  -L/usr/lib64 -lhiredis redis-test.c -o redis-test

$ time ./redis-test
./redis-test  0.04s user 0.25s system 48% cpu 0.592 total

$ redis-cli HGET foo bar
"10000"
#include <stdio.h>
#include <hiredis.h>
#include <assert.h>

#define IP "127.0.0.1"
#define PORT 6379
#define COUNT 10000

int main(){
    redisContext *c = redisConnect(IP, PORT);
    if (c != NULL && c->err) {
        printf("Error: %s\n", c->errstr);
        return 1;
    }
    unsigned int i=0;
    for(; i<COUNT; i++) {
        redisReply *reply;
        reply = redisCommand(c,"HINCRBY foo bar 1");
        if(reply){ 
            freeReplyObject(reply);
        }
    }
    redisFree(c);
    return 0;
}

Apache Moduleへの組み込み

Moduleを入れる前のPerformance

Redisに接続するApache Moduleを入れる前のPerformanceを見てみます。4,5年前に購入したPCで試しているのでさほどSpeedが出ていませんが、ApacheのSampleページ表示で並列10/合計1万のabベンチマークの場合、2065.80rpsとなりました。

$ cat /proc/meminfo 
MemTotal:        2327156 kB
MemFree:         2058828 kB
Buffers:           21396 kB
Cached:            94164 kB
SwapCached:            0 kB

$ ab -n 10000 -c 10 "http://localhost/"

Concurrency Level:      10
Time taken for tests:   4.841 seconds
Complete requests:      10000
Failed requests:        0
Write errors:           0
Non-2xx responses:      10006
Total transferred:      52401422 bytes
HTML transferred:       50420234 bytes
Requests per second:    2065.80 [#/sec] (mean)
Time per request:       4.841 [ms] (mean)
Time per request:       0.484 [ms] (mean, across all concurrent requests)
Transfer rate:          10571.35 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    2   1.4      2      32
Processing:     1    3   1.9      2      64
Waiting:        0    2   1.5      2      36
Total:          2    5   2.4      4      67
Apache ModuleからRedisへの書き込み

次にRedisに接続する為のApache Moduleを入れて行きます。まずは接続設定をapacheの設定ファイルに記述します。ここでは新たにredis.confを用意しました。
次にRedisに接続する為のmod_redisという自作Moduleを入れて行きます。apxsコマンドで入れて、apacheをrestartします。
一回curlで接続してみてRedisのPermission deniedで怒られたらhttpd_can_network_connect=1設定して上げましょう。

$ sudo vim /etc/httpd/conf.d/redis.conf
RedisHost 127.0.0.1
RedisPort 6379

$ sudo apxs -i -a -c -I/usr/include/hiredis -L/usr/lib64 -lhiredis mod_redis.c
$ sudo /etc/init.d/httpd restart
$ curl "http://localhost/redis"  
[Fri Dec 06 01:15:43 2013] [error] [client ::1] Redis Connection Error : Permission denied

$ sudo /usr/sbin/setsebool httpd_can_network_connect=1
#include "httpd.h"
#include "http_config.h"
#include "http_protocol.h"
#include "apr_hash.h"
#include "apr_tables.h"
#include "apr_strings.h"
#include "ap_config.h"
#include "util_script.h"
#include "http_log.h"
#include "hiredis.h"

typedef struct {
  int port;
  char *host;
} redis_env;

module AP_MODULE_DECLARE_DATA redis_module;

static int redis_handler(request_rec *r) {
  redis_env *db = ap_get_module_config(r->per_dir_config, &redis_module);
  redisContext *c = redisConnect(db->host, db->port);
  if (c != NULL && c->err) {
    ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, "Redis Connection Error : %s", c->errstr);
    return DECLINED;
  }
  redisReply *reply;
  reply = redisCommand(c,"HINCRBY foo bar 1");
  if(reply){ 
  	freeReplyObject(reply);
  }
  reply = redisCommand(c,"QUIT");
  if(reply){ 
  	freeReplyObject(reply);
  }
  redisFree(c);
  return OK;
}

static void *make_redis_dir(apr_pool_t *p, char *d) {
  redis_env *db;
  db = (redis_env *) apr_pcalloc(p, sizeof(redis_env));
  return db;
}

static const char *set_redis_host(cmd_parms *cmd, void *mconfig, const char *name) {
  redis_env *db;
  db = (redis_env *) mconfig;
  db->host = ap_getword_conf(cmd->pool, &name);
  return NULL;
}

static const char *set_redis_port(cmd_parms *cmd, void *mconfig, const char *port) {
  redis_env *db;
  db = (redis_env *) mconfig;
  char *p;
  p = ap_getword_conf(cmd->pool, &port);
  db->port = atoi(p);
  return NULL;
}

static const command_rec redis_conf_cmds[] = {
  AP_INIT_TAKE1("RedisHost", set_redis_host, NULL, OR_FILEINFO, "redis hostname"),
  AP_INIT_TAKE1("RedisPort", set_redis_port, NULL, OR_FILEINFO, "redis port"),
  {NULL}
};

static void redis_register_hooks(apr_pool_t *p) {
	ap_hook_handler(redis_handler, NULL, NULL, APR_HOOK_MIDDLE);
}

module AP_MODULE_DECLARE_DATA redis_module = {
	STANDARD20_MODULE_STUFF, 
	make_redis_dir,        /* create per-dir    config structures */
	NULL,                  /* merge  per-dir    config structures */
	NULL,                  /* create per-server config structures */
	NULL,                  /* merge  per-server config structures */
	redis_conf_cmds,       /* table of config file commands       */
	redis_register_hooks   /* register hooks                      */
};
Moduleを入れた後のPerfomanceテスト

RedisModuleを入れた後のPerformanceテストをしてみます。上と同様に並列10/合計1万のabベンチマークで実行した場合、726.98rpsとなりました。実行後にRedisのHashの値も10000に更新されています。

$ ab -n 10000 -c 10 "http://localhost/redis"
Concurrency Level:      10
Time taken for tests:   13.756 seconds
Complete requests:      10000
Failed requests:        0
Write errors:           0
Total transferred:      1670000 bytes
HTML transferred:       0 bytes
Requests per second:    726.98 [#/sec] (mean)
Time per request:       13.756 [ms] (mean)
Time per request:       1.376 [ms] (mean, across all concurrent requests)
Transfer rate:          118.56 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    3   4.7      2      76
Processing:     1   11  10.3      8     228
Waiting:        0    9   9.2      7     211
Total:          1   14  11.0     11     228

$ redis-cli HGET foo bar  
"10000"

もう少しRedisをいじめてみます。上のabスクリプトを更に繰り返し10回実行してみます。そうするとFailed Requestが多発し226.90rpsまでパフォーマンスが落ちています。この原因はRedisへの接続でTIME_WAITが大量に発生しているので、ApacheがRedisとの接続エラーを返しているためと思われます。Apacheerror_logを見てもRedis Connection Error : Cannot assign requested addressのように記載されているのでConnectionErrorである事は間違いないと思います。

$ for i in {1..10}
do
ab -n 10000 -c 10 "http://localhost/redis"
done

Concurrency Level:      10
Time taken for tests:   44.073 seconds
Complete requests:      10000
Failed requests:        2619
   (Connect: 0, Receive: 0, Length: 2619, Exceptions: 0)
Write errors:           0
Total transferred:      2015708 bytes
HTML transferred:       81189 bytes
Requests per second:    226.90 [#/sec] (mean)
Time per request:       44.073 [ms] (mean)
Time per request:       4.407 [ms] (mean, across all concurrent requests)
Transfer rate:          44.66 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    4   8.5      0      75
Processing:     1   40  49.0     18    1188
Waiting:        0   36  46.7     16    1096
Total:          2   44  51.1     21    1188

$ netstat | grep "localhost:6379" 
tcp        0      0 localhost:37067             localhost:6379              TIME_WAIT   
tcp        0      0 localhost:37730             localhost:6379              TIME_WAIT   
tcp        0      0 localhost:45624             localhost:6379              TIME_WAIT   
tcp        0      0 localhost:52429             localhost:6379              TIME_WAIT

$ netstat | grep "localhost:6379" | grep TIME_WAIT | wc -l
19309

$ tail -f /var/log/httpd/error_log
[Fri Dec 06 00:42:17 2013] [error] [client ::1] Redis Connection Error : Cannot assign requested address
[Fri Dec 06 00:42:17 2013] [error] [client ::1] Redis Connection Error : Cannot assign requested address
[Fri Dec 06 00:42:17 2013] [error] [client ::1] Redis Connection Error : Cannot assign requested address
[Fri Dec 06 00:42:17 2013] [error] [client ::1] Redis Connection Error : Cannot assign requested address
[Fri Dec 06 00:42:17 2013] [error] [client ::1] Redis Connection Error : Cannot assign requested address
Cannot assign requested addressの原因を探る

straceを使ってredis-serverの内部処理とCannot assign requested addressが発生している時にどんな処理が行われているのかを見てみます。結論としては良く分からず...。Redisのメモリからbackground saveでdiskに移す時が怪しいと思っていたんですが、どうやらあまり関係無かったようです。同じようにredis-cli slowlog getでslow queryを取得してstraceのlogと照らし合わせてみましたが、これといって変な処理は入っていませんでした。単純にmemoryを大量に消費した時の問題か...この辺り詳しい方教えて頂けると助かります。

$ sudo strace -t -f -p `pgrep redis-server` > redis-log 2>&1

$ tail -f /var/log/httpd/error_log
[Fri Dec 06 01:32:15 2013] [error] [client ::1] Redis Connection Error : Cannot assign requested address

$ grep "01:32:15" redis-log | vim -
[pid  1393] 01:32:15 read(9, "*1\r\n$4\r\nQUIT\r\n", 16384) = 14
[pid  1393] 01:32:15 epoll_ctl(3, EPOLL_CTL_MOD, 9, {EPOLLIN|EPOLLOUT, {u32=9, u64=9}}) = 0 
[pid  1393] 01:32:15 write(6, ":932884\r\n", 9) = 9 
[pid  1393] 01:32:15 epoll_ctl(3, EPOLL_CTL_MOD, 6, {EPOLLIN, {u32=6, u64=6}}) = 0 
[pid  1393] 01:32:15 read(5, "*4\r\n$7\r\nHINCRBY\r\n$3\r\nfoo\r\n$3\r\nba"..., 16384) = 42
[pid  1393] 01:32:15 epoll_ctl(3, EPOLL_CTL_MOD, 5, {EPOLLIN|EPOLLOUT, {u32=5, u64=5}}) = 0 
[pid  1393] 01:32:15 epoll_wait(3, {{EPOLLIN, {u32=4, u64=4}}, {EPOLLOUT, {u32=9, u64=9}}, {EPOLLIN, {u32=6, u64=6}}, {EPOLLOUT, {u32=5, u64=5}}, {EPOLLIN, {u32=7, u64=7}}}, 10240, 98) = 5 
[pid  1393] 01:32:15 accept(4, {sa_family=AF_INET, sin_port=htons(35569), sin_addr=inet_addr("127.0.0.1")}, [16]) = 8 
[pid  1393] 01:32:15 fcntl(8, F_GETFL)  = 0x2 (flags O_RDWR)
[pid  1393] 01:32:15 fcntl(8, F_SETFL, O_RDWR|O_NONBLOCK) = 0 
[pid  1393] 01:32:15 setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0 
[pid  1393] 01:32:15 epoll_ctl(3, EPOLL_CTL_ADD, 8, {EPOLLIN, {u32=8, u64=8}}) = 0 
[pid  1393] 01:32:15 write(9, "+OK\r\n", 5) = 5 
[pid  1393] 01:32:15 epoll_ctl(3, EPOLL_CTL_MOD, 9, {EPOLLIN, {u32=9, u64=9}}) = 0 
[pid  1393] 01:32:15 epoll_ctl(3, EPOLL_CTL_DEL, 9, {0, {u32=9, u64=9}}) = 0 
[pid  1393] 01:32:15 close(9)           = 0 


$ redis-cli slowlog get
 1) 1) (integer) 69
    2) (integer) 1386261178
    3) (integer) 67530
    4) 1) "HINCRBY"
       2) "foo"
       3) "bar"
       4) "1"
 2) 1) (integer) 68
    2) (integer) 1386261168
    3) (integer) 14837
    4) 1) "HINCRBY"
       2) "foo"
       3) "bar"
       4) "1"
どうやって問題を解決するか?

僕が思いついたのは1.LinuxのKernel設定を修正する2.Apache Module内でmutexによりConnectionを共有する3.Redisの設定ファイルを修正してチューニングするの3つです。2.は既にmod_redisがやっています。sneakybeaky/mod_redis はてなブックマーク - sneakybeaky/mod_redis 3.はRedisの運用を細かくやってみないとできなそうな気がしたので、ここでは1の例を紹介します。


net.ipv4.tcp_tw_recycleというsysctlのパラメータを1に設定します。このパラメータは高速にSocketのRecycle処理をしてくれます。ただし導入する時は注意してください。同一IPからのアクセスは直ぐにSocketを解放してしまう可能性があるためです。十分なテストをしてから導入しましょう。


今回は導入した結果、Failed requestsが無くなりCannot assign requested addressがerror_logに表示されなくなり更にrpsも1912.64まで上がるという非常に効果の良い設定となりました。実行結果もRequest数に従った登録結果になっています。


今回の件とはあまり関係ありませんが、その他kernel関係の設定でvm.overcommit_memory=1のように設定するとbackground save時にmemoryの問題が回避される等の事例があるので、時間がある時に検証してみたいと思います。Redisを使う時は見積の二倍の容量必要だよね、という話 - Qiita [キータ] はてなブックマーク - Redisを使う時は見積の二倍の容量必要だよね、という話 - Qiita [キータ]

$ sudo vim /etc/sysctl.conf
net.ipv4.tcp_tw_recycle = 1

$ sudo sysctl -p

$ for i in {1..10}
do
ab -n 10000 -c 10 "http://localhost/redis"
done

Concurrency Level:      10
Time taken for tests:   5.228 seconds
Complete requests:      10000
Failed requests:        0
Write errors:           0
Total transferred:      1670835 bytes
HTML transferred:       0 bytes
Requests per second:    1912.64 [#/sec] (mean)
Time per request:       5.228 [ms] (mean)
Time per request:       0.523 [ms] (mean, across all concurrent requests)
Transfer rate:          312.08 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    2   1.9      2      23
Processing:     1    5   3.6      4     131
Waiting:        0    4   3.3      3     105
Total:          1    7   3.5      7     134

$ redis-cli HGET foo bar 
"100039"

スポンサーリンク