memcached 1.4.6でmixiの障害の原因となったaccept_new_connsがスレッドセーフじゃない件は修正されているはずだったのですが、検証したところ別のスレッド競合による不具合が発生し、Bugは全て解消されてはいませんでした。
この件についてmixiたんぽぽGの森本さんと調査していたところ、memcachedのcommiterにtwitter上で補足され、つたない英語で報告をあげていたら1.4.7-rc1で修正されたのでその報告。
memcached 1.4.6での不具合再現方法
まず、1.4.6で不具合を再現させる方法について。mixiのエンジニアブログと同じように、memcachedは次のオプションで起動し、
$ ./memcached -U 0 -u nobody -p 11222 -t 4 -m 16000 -C -c 1000 -v
malaさん作のテストスクリプトによって負荷をかけます。その際にスクリプトにこのpatchをあてています。再現させる環境としてOSにCentOS5.6、Xeon L3426(4core/8thread)を積んだサーバを使い、16並列でmemcachedにアクセスします
$ ./memcachedos.pl 127.0.0.1 11222 16
...
TIME:73176 PID:7292 Connect:47421822 QPS:835 Active:129 Success:18800016 Closed:18799887 Fail:28621806 Msg:Connection timed out
...
この環境にて、5分から2時間ぐらいので間で、dosツールがだすメッセージのQPSが0に限りなく近くなったら再現成功です。この状態でmemcachedos.plを止め、telnetでmemcachedにアクセスをしてみます
$ telnet 127.0.0.1 11222
..
stats
おそらく接続はできるけど、一切コマンドへの応答がないはずです。quitもできません。
memcached 1.4.6での修正内容と問題点
詳しくは、mixiのエンジニアブログを参照してもらうとよいですが、memcached 1.4.6ではスレッド間の競合をさけるため、accept_new_connsを各スレッドで変更するのではなく、timerを使いメインスレッドにて変更を行うようになりました。
mixiエンジニアblogから転載(一部追加)した、簡略化したコード
main thread : do_accept_new_conns {
if(受付無理){
allow_new_conns = false; // allow_new_connsを落とす
maxconns_handler起動
}
}
worker thread : conn_close {
allow_new_conns = true; // 接続に余裕ができた
}
main thread : maxconns_handler {
if(not allow_new_conns){
// まだ接続に余裕がない
10msにもう一度調べる
}else{
timer削除
accept_new_conns(true); // 新規接続受付開始;
}
}
// thread.c
void accept_new_conns(const bool do_accept) {
pthread_mutex_lock(&conn_lock);
do_accept_new_conns(do_accept);
pthread_mutex_unlock(&conn_lock);
}
接続エラーが起きた際の処理は、
- (1) drive_machineからaccept_new_conns(false)が呼び出される
- (2) do_accept_new_connsでallow_new_connsをfalseにし、maxconns_handlerを呼び出す
- (3) maxconns_handlerはallow_new_connsをみて、falseの場合timerを使い10ms後に、自分自身を呼びだす
- (4) 他のクライアントからの接続が切れると、allow_new_connsをtrueにする
- (5) timerから呼び出されたmaxconns_handlerがallow_new_connsがtrueであればaccept_new_conns(true)する
となっています。
ここでものすごく稀なケースとして、(2)と(3)の間に(4)が入ると、(3) でtimer処理ではなく、いきなりaccept_new_conns(true)を呼び出してしまい、pthread_mutex_lock(&conn_lock) でdead lockする。これが今回の問題でした。
accept_new_conns => pthread_mutex_lock(&conn_lock) => do_accept_new_conns
=>
=> maxconns_handler => accept_new_conns =>
pthread_mutex_lock(&conn_lock)
と処理がループしてしまっているわけですね
gdbでもそれが確認できます
(gdb) bt
#0 0x000000391c80d4c4 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x000000391c808e1a in _L_lock_1034 () from /lib64/libpthread.so.0
#2 0x000000391c808cdc in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000040db6d in accept_new_conns (do_accept=true) at thread.c:183
#4 0x0000000000402924 in maxconns_handler (fd=<value optimized out>, which=<value optimized out>, arg=<value optimized out>) at memcached.c:140
#5 0x000000000040db75 in accept_new_conns (do_accept=false) at thread.c:184
...
省略
...
(gdb) p conn_lock
$1 = {__data = {__lock = 2, __count = 0, __owner = 19110, __nusers = 1, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}},
__size = "\002\000\000\000\000\000\000\000\246J\000\000\001", '\000' <repeats 26 times>, __align = 2}
(gdb) p allow_new_conns
$2 = true
thread.cのmutex_lockで止まっていて、allow_new_connsにtrueが入っています。
修正patch
んで、次が今回の修正箇所。
diff --git a/memcached.c b/memcached.c
index 7905e6c..c82f5c5 100644
--- a/memcached.c
+++ b/memcached.c
@@ -130,7 +130,7 @@ static struct event maxconnsevent;
static void maxconns_handler(const int fd, const short which, void *arg) {
struct timeval t = {.tv_sec = 0, .tv_usec = 10000};
- if (allow_new_conns == false) {
+ if (fd == -42 || allow_new_conns == false) {
/* reschedule in 10ms if we need to keep polling */
evtimer_set(&maxconnsevent, maxconns_handler, 0);
event_base_set(main_base, &maxconnsevent);
@@ -3386,7 +3386,7 @@ void do_accept_new_conns(const bool do_accept) {
stats.listen_disabled_num++;
STATS_UNLOCK();
allow_new_conns = false;
- maxconns_handler(0, 0, 0);
+ maxconns_handler(-42, 0, 0);
}
}
maxconns_handlerの初回呼び出し時に特殊なfdとして「-42」与え、必ずtimerが起動するようになりました。-42がそのまま書いてあるところがいまいち感がありますがこれで問題がなくなりました。
今、同じ環境で1.4.7-rc1に対して、memcachedos.plを使い負荷をかけていますが、20時間以上は問題なく動作しています。
これでmixiの障害の原因となったmemcachedのバグは全て修正されたはずです。memcached-1.4.7の正式リリースが待ち遠しいです。
もう一年たったんですねぇ〜
