仕事でagを利用していた時に出会ったバグを、先輩たちの力を借りてなんとかした話です。
先に結論を書くと、業務に用いていたagのバージョンが古いのが原因のようでした。version 0.15より古いとlockの実装に問題があるようです。
$ ag --version
ag version 0.14pre以下、問題の発覚からなんとかするまでの記録です。
発端
agが途中で止まる
時折、agのファイル操作が先へ進まなくなってしまう不具合がありました。 操作中に対象ファイルのロック状況が変わるとデッドロックが発生しているのでは？と想像。 気になってstraceでプロセスにアタッチすると、以下で停止していることが分かりました。
[pid 4589] futex(0x80517e4, FUTEX_WAIT, 32159, NULL
FUTEX_WAIT
futex(2)を引くと、futex(2)の書式に対する操作FUTEX_WAITの説明があります。
int futex(int *uaddr, int op, int val, const struct timespec *timeout,
int *uaddr2, int val3);この操作は futex アドレス uaddr に指定された値 val がまだ格納されているかどうかを不可分操作で検証し、 sleep 状態で この futex アドレスに対して FUTEX_WAKE が実行されるのを待つ。 timeout 引き数が … NULL の場合、 呼び出しは無限に停止する。 引き数 uaddr2 と val3 は無視される。…
FUTEX_WAKEがなんらかの理由によって実行されず、待ち状態が終わらないようでした。
バックトレース
もう少し詳しく調べるため、上記の状態で止まったままのagのコアダンプをgcoreで取得。
$ gcore -o /tmp/ag_suspended.core 22650コアダンプをgdbで読み込み。
$ gdb /usr/bin/ag ag_suspended.core.22650
GNU gdb Red Hat Linux (6.3.0.0-1.162.el4rh)
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "i386-redhat-linux-gnu"...(no debugging symbols found)
Using host libthread_db library "/lib/tls/libthread_db.so.1".
Core was generated by `/usr/bin/ag'.
Reading symbols from /lib/libpcre.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib/libpcre.so.0
Reading symbols from /usr/lib/libz.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libz.so.1
Reading symbols from /lib/tls/libpthread.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib/tls/libpthread.so.0
Reading symbols from /lib/tls/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/tls/libc.so.6
Reading symbols from /lib/ld-linux.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /lib/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib/libgcc_s.so.1
#0 0x0053b7a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2スレッド数の確認。2つあります。
(gdb) info thread
2 process 22650 0x0053b7a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
* 1 process 22663 0x0053b7a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2スレッド1のバックトレース。
pthread_cond_wait()で停止していることが分かります。
(gdb) bt
#0 0x0053b7a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
#1 0x00c65ef6 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/tls/libpthread.so.0
#2 0x0804c9bf in search_file_worker ()
#3 0x00c635cc in start_thread () from /lib/tls/libpthread.so.0
#4 0x0062535e in clone () from /lib/tls/libc.so.6スレッド2のバックトレース。
pthread_join()で停止していることが分かります。
(gdb) thread 2
[Switching to thread 2 (process 22650)]#0 0x0053b7a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
(gdb) bt
#0 0x0053b7a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
#1 0x00c64497 in pthread_join () from /lib/tls/libpthread.so.0
#2 0x0804e74c in main ()the silver searcherのコードを調べる
仕事で使っていたagのversionが0.14preだったため、以下に示すコードのTagも0.14にしています。
main.c
pthread_join(3)はsrc/main.cのL127 (at 0.14) で呼ばれているようです。
int pthread_join(pthread_t th, void **thread_return);pthread_join は、 呼び出しスレッドの実行を停止し、 th で指定したスレッドが pthread_exit(3) を呼び出して終了するか、取り消しされて終了するのを待つ。
search.c
pthread_cond_wait(3)はsrc/search.cのL265 (at 0.14) で呼ばれているようです。
pthread_cond_wait は ( pthread_mutex_unlock による) mutex のアンロックと条件変数 cond の送信に対する待機を一息で行う。条件変数が送信されるまで スレッドの実行は停止され、CPU 時間を消費することはない。 mutex は、 pthread_cond_wait の開始時点で、これを呼び出すスレッドによってロックされていなければ ならない。 呼び出し側のスレッドに戻る前に pthread_cond_wait は mutex を ( pthread_mutex_lock によって)再び獲得する。
mutex のアンロックと条件変数に対する待機は一息に行われる。従って、 全てのスレッドが条件を送信する前に常に mutex を獲得するのならば、 スレッドが mutex をアンロックする時点と、それが条件変数を待つ時点 との中間の時点で、条件の送信が行なわれる(従って無視される)ことが 不可能となることが保証される。
work_queue_mutexのPull Request
上記2つの周辺コードが怪しいのではないか？と調べている内に、自分が遭遇した問題と全く同じIssue、そしてそれを改善しているプルリクを発見。
ensure work_queue_mutex is locked when signaling files_ready.
(Apparently) Fixes #182
上のプルリクがmergeされたcommitは Merge pull request #224 from jmesmon/fix_182 · 83fdc49 · ggreer/the_silver_searcher で、このcommitが含まれるagのバージョン一覧を見ると…、
$ git tag --contain 83fdc49
0.15
0.16
0.17
0.18
0.18.10 . 1 5 ! ?
結論
仕事で使っていたagのバージョンは0.14pre、そして上記のバグ修正comittがmergeされたのは0.15以上。
$ ag --version
ag version 0.14preとほほ…。
というわけで、早速agのバージョンを上げたのでした。
終わりに
問題解決にあたって、tnmt先輩、hiboma先輩、udzura先輩にとてもお世話になりました。 社内IRCの#kernelチャンネルでワイワイしていてとても楽しかったです。
プログラムに不審な挙動が見られた時に、どういう順序でアプローチし、解決していけばいいのかということを勉強させていただきました。
結果バージョンアップすれば良いというオチではありましたが、得たものはそれ以上に多かったし大きかったです。
おしまい。