Bug #114
shutdown コマンドでサーバが正常に終了しない場合がある
| Status: | 完了 | Start date: | 02/26/2010 | |
|---|---|---|---|---|
| Priority: | High | Due date: | ||
| Assignee: |  Toshihisa Tashiro |
% Done: | 0% |
|
| Category: | - | |||
| Target version: | 1.1 |
Description
steps
shutdown コマンドをgroonga サーバに送信する。
result
まれにサーバが終了しない場合がある。
expect
shutdown コマンドを正常に受け付けたなら確実に正常終了する。
History
Updated by Tasuku SUENAGA about 2 years ago
- Target version set to 1.0
Updated by daijiro MORI about 2 years ago
- Assignee set to daijiro MORI
Updated by Ryo Onodera about 2 years ago
- Priority changed from Normal to High
Updated by daijiro MORI over 1 year ago
- Target version changed from 1.0 to 1.1
Updated by daijiro MORI over 1 year ago
- Assignee changed from daijiro MORI to Toshihisa Tashiro
再現手順を示してください。
Updated by Toshihisa Tashiro over 1 year ago
- File check_shutdown.sh added
groonga -c をバッチで処理できるよう手を加えてから、添付のシェルスクリプトを実行。
12時間以上成功している。ので、いつのまにか治ったのかもしれない。
あるいはgrntestのバグ、あるいはある程度負荷をかけないと起きない？
さらに検証する。
Updated by Toshihisa Tashiro over 1 year ago
#/bin/bash
while :
do
rm -f check_db*
grntest --noftp test.scr check_db
done
というスクリプトで単純にgrntestを繰り返したところ、2158回目で
shutdownできなくなった。grntestなら最新のgroongaでも発生する。grntestを使わず、
groonga 本体だけで発生するかどうか追求する。
Updated by Toshihisa Tashiro over 1 year ago
do
groonga -s /tmp/check_db &
pid=$!
- echo "pid = $pid"
sleep 2
echo "status" | groonga -c &
echo "status" | groonga -c &
echo "status" | groonga -c &
echo "shutdown" | groonga -c
sleep 2
isalive=`ps -ef | grep $pid | grep -v grep | wc -l`
if [ $isalive -eq 1 ]; then
kill -6 $pid
echo "killed $pid: shutdown failed! core dumped"
break
fi
echo "shutdown success! $count"
count=`expr $count + 1`
done
とするとgroonga単体でもすぐshutdownできない状態になる。
こんな使い方がいいかはともかく、こんな場合でもきちんとshutdown すべき。
ちなみにabortして止まったところは、
#0 0x00007f16caa99ff1 in nanosleep () from /lib/libc.so.6
(gdb) where
#0 0x00007f16caa99ff1 in nanosleep () from /lib/libc.so.6
#1 0x00007f16caac54c4 in usleep () from /lib/libc.so.6
#2 0x0000000000405dac in g_server (path=0x7fffd3c468f2 "/tmp/check_db")
at groonga.c:1824
#3 0x000000000040af25 in main (argc=3, argv=0x7fffd3c46338) at groonga.c:2305
g_serverの
1820 for (;;) {
1821 MUTEX_LOCK(q_mutex);
1822 if (nthreads == nfthreads) { break; }
1823 MUTEX_UNLOCK(q_mutex);
1824 usleep(1000);
1825 }
で無限ループにおちいってshutdownできないようだ。
この時、
(gdb) print nthreads
$1 = 0
(gdb) print nfthreads
$2 = 1
この値が正常なのかどうか調べる。
Updated by Toshihisa Tashiro over 1 year ago
サーバーだけのログを出力してみた。
2010-10-06 03:20:56.000000|n| grn_init
2010-10-06 03:20:56.000000|n| RLIMIT_NOFILE(1024,1024)
2010-10-06 03:20:58.000000|n| thread start (0/2)
2010-10-06 03:20:58.000000|n| thread start (0/3)
2010-10-06 03:20:58.000000|n| thread start (0/4)
2010-10-06 03:20:58.000000|n| thread end (0/3)
2010-10-06 03:20:58.000000|n| thread end (0/2)
2010-10-06 03:20:58.000000|n| thread start (0/4)
2010-10-06 03:20:58.000000|n| thread end (0/1)
2010-10-06 03:20:58.000000|n| thread end (0/0)
2010-10-06 03:20:58.000000|n| grn_fin (0)
2010-10-06 03:21:00.000000|n| grn_init
2010-10-06 03:21:00.000000|n| RLIMIT_NOFILE(1024,1024)
2010-10-06 03:21:02.000000|n| thread start (0/2)
2010-10-06 03:21:02.000000|n| thread end (0/0)
2010-10-06 03:21:02.000000|n| grn_fin (0)
2010-10-06 03:21:04.000000|n| grn_init
2010-10-06 03:21:04.000000|n| RLIMIT_NOFILE(1024,1024)
2010-10-06 03:21:06.000000|n| thread start (0/2)
2010-10-06 03:21:06.000000|n| thread end (0/0)
2010-10-06 03:21:06.000000|n| grn_fin (0)
2010-10-06 03:21:08.000000|n| grn_init
2010-10-06 03:21:08.000000|n| RLIMIT_NOFILE(1024,1024)
2010-10-06 03:21:10.000000|n| thread start (0/2)
2010-10-06 03:21:10.000000|n| thread start (0/4)
2010-10-06 03:21:10.000000|n| thread start (0/4)
2010-10-06 03:21:10.000000|n| thread end (2/2)
2010-10-06 03:21:10.000000|n| grn_fin (0)
2010-10-06 03:21:12.000000|n| grn_init
2010-10-06 03:21:12.000000|n| RLIMIT_NOFILE(1024,1024)
2010-10-06 03:21:14.000000|n| thread start (0/2)
2010-10-06 03:21:14.000000|n| thread start (0/3)
2010-10-06 03:21:14.000000|n| thread end (1/1)
2010-10-06 03:21:14.000000|n| thread end (1/0) <--ここで無限ループ。
分母＜分子 になることが想定外なのかもしれない。
Updated by Toshihisa Tashiro over 1 year ago
@ -1817,7 +1819,7 @ g_server(char *path)
}
for (;;) {
MUTEX_LOCK(q_mutex);
- if (nthreads == nfthreads) { break; }
+ if (nthreads <= nfthreads) { break; }
MUTEX_UNLOCK(q_mutex);
usleep(1000);
}
とすると、前述のスクリプトでも長時間動く。grntestでも調べる。
Updated by daijiro MORI over 1 year ago
nthreads <= nfthreads のように条件を変えると、クエリ実行中のスレッドを止めてしまうので望ましくないです。
次回再現した時には、まず当該groongaプロセスがcpuをどの程度消費しているか確認して下さい。
それからgdbでアタッチし全てのスレッドについて、何をやっているか確認してください。
mainスレッドは上のloopで止まっていると思いますが、全てのworkerスレッドがcond_waitか何かで
眠っているのだったら、nfthreadsを更新する処理のバグだと思います。
Updated by Toshihisa Tashiro over 1 year ago
無限ループに入った段階で、cpu消費は0% から70%を行ったり来たり。
残っているのはメインスレッドのみ・・・
(gdb) thread 1
[Switching to thread 1 (Thread 0x7f5fe339a6e0 (LWP 6185))]#0 0x00007f5fe21fbff1 in nanosleep () from /lib/libc.so.6
(gdb) where
#0 0x00007f5fe21fbff1 in nanosleep () from /lib/libc.so.6
#1 0x00007f5fe22274c4 in usleep () from /lib/libc.so.6
#2 0x0000000000405dac in g_server (path=0x7f5fd98f4184 "") at groonga.c:1824
#3 0x000000000040af25 in main (argc=5, argv=0x7fffeb3a7a78) at groonga.c:2305
やはり
(gdb) print nthreads
$1 = 0
(gdb) print nfthreads
$2 = 1
という状態。
Updated by Toshihisa Tashiro over 1 year ago
なんど繰り返しても同じ状態になる。
ので、@ -1632,12 +1634,14 @ g_worker(void *arg)
grn_ctx *ctx;
grn_edge *edge;
nfthreads++;
+GRN_LOG(&grn_gctx, GRN_LOG_NOTICE, "nfthreads increment=%d", nfthreads);
while (!(edge = (grn_edge *)grn_com_queue_deque(&grn_gctx, &ctx_new))) {
COND_WAIT(q_cond, q_mutex);
if (grn_gctx.stat == GRN_CTX_QUIT) { goto exit; }
}
ctx = &edge->ctx;
nfthreads--;
+GRN_LOG(&grn_gctx, GRN_LOG_NOTICE, "nfthreads decrement=%d", nfthreads);
if (edge->stat EDGE_DOING) { continue; }
if (edge->stat EDGE_WAIT) {
edge->stat = EDGE_DOING;
としてnfthreads のログを取ってみた。
2010-10-06 23:54:03.000000|n| grn_init
2010-10-06 23:54:03.000000|n| RLIMIT_NOFILE(1024,1024)
2010-10-06 23:54:05.000000|n| thread start (0/2)
2010-10-06 23:54:05.000000|n| nfthreads increment=1
2010-10-06 23:54:05.000000|n| nfthreads decrement=0
2010-10-06 23:54:05.000000|n| thread start (0/3)
2010-10-06 23:54:05.000000|n| nfthreads increment=1
2010-10-06 23:54:05.000000|n| nfthreads decrement=0
2010-10-06 23:54:05.000000|n| nfthreads increment=1
2010-10-06 23:54:05.000000|n| nfthreads increment=2
2010-10-06 23:54:05.000000|n| nfthreads decrement=1
2010-10-06 23:54:05.000000|n| nfthreads increment=2
2010-10-06 23:54:05.000000|n| nfthreads decrement=1
2010-10-06 23:54:05.000000|n| nfthreads increment=2
2010-10-06 23:54:05.000000|n| nfthreads decrement=1
2010-10-06 23:54:05.000000|n| nfthreads increment=2
2010-10-06 23:54:05.000000|n| nfthreads decrement=1
2010-10-06 23:54:05.000000|n| thread end (1/1)
2010-10-06 23:54:05.000000|n| thread end (1/0)
2010-10-06 23:54:05.000000|n| thread end (1/1)
のところで終了するのが本当なのか・・・
Updated by daijiro MORI over 1 year ago
変数のdecrementしわすれを直しました！これで再現するか見ていただけますか？
Updated by Toshihisa Tashiro over 1 year ago
- Status changed from 担当者作業中 to 完了チェック待ち
以前は１０回も繰り返せばshutdown できなくなっていた#9のスクリプト
が１０００回以上成功する。
念のため、g_worker の
nfthreads--;
をコメントアウトすると、またすぐにshutdown できなくなる。
ので、おそらくちゃんと直っている。
groonga -c --file
(http://redmine.groonga.org/issues/578)
の件が直れば完了。
Updated by Toshihisa Tashiro over 1 year ago
- Status changed from 完了チェック待ち to 要連絡・告知
ふと気づいたのですが、h_workerの該当部分も同様の処理が必要なのではないでしょうか？
Updated by daijiro MORI over 1 year ago
- Status changed from 要連絡・告知 to 完了チェック待ち
その通りでした！ありがとうございます！h_worker()にも同様の処理を入れました。
Updated by daijiro MORI over 1 year ago
- Status changed from 完了チェック待ち to 完了