yesodアプリケーションがデッドロック状態になってしまうことがわかってきましたがそれ以外は何もわかりません

goofysを使わない新しい構成のシステムがちゃんと動くか確認するためにステージング環境を整えます.

構築方法はちゃんとメモしているのですが,流石に面倒くさくなってきた.ansibleとか使えば楽できるんでしょうか…環境構築なんか1回だけと思ってましたが,結構な数をこなしてきたので,いい加減導入を考えたほうが良いのかもしれません.

しかしステージング環境と本番環境で埋め込む変数が異なったりするのですが,そのへんをansibleはどうやって処理するんだろう,と思ってググったら環境ごとにファイルを分けるのか…しかし,今回のデプロイは実験的なものが動くのか試しているわけで,ブランチがmasterじゃないわけだがそういうのどうするべきかなあと思って面倒臭くなった.数ステップで終了する単一のアプリケーションだし,ansibleを導入するほどの案件じゃないのかもしれない.

本番環境がt2.xlargeなのでステージング環境も同じくt2.xlargeにしてstack buildしてみたらビルドが高速でビックリした,手元のデスクトップPCもこれぐらいの環境を用意したくなってきますね.

テストアップロードに1GBのファイルをアップロードしてみたらかなりCPUを消費していることがわかった.なんでだ…?そんなにCPUを使うことは無いと思うんですが,HTTPSを使ってるからファイルの暗号化に手間取っているのかな?

テスト中にステージング環境が落ちた.goofysを使わないでS3 APIを直接使うようにしても落ちるのは変わらないということかー…マジか…しかし,本番環境はすぐ復旧しないといけなくて,これまでステージング環境で落ちることは無かったので,やっと調査することができます.

とりあえずgdb -pでattachしてみることにしました.rootユーザーじゃないとattachできないのに気が付かなかった.実行ユーザーが同じなら問題ないかと思っていた…

btしても??だらけで一番上がpthread_cond_waitで何もわからない.元がhaskellコードでしかもthreadを使いまくりのyesodだから当たり前なんですけど…せめて何処で止まっているのか調べたかった.

バックトレースが

(gdb) bt
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x0000000003ef8399 in ?? ()
#2  0x0000000003edc46b in ?? ()
#3  0x0000000003ee56ef in ?? ()
#4  0x0000000003ee6dbc in ?? ()
#5  0x0000000003ee30e7 in ?? ()
#6  0x0000000000414ad4 in ?? ()
#7  0x00007fb5a80c7830 in __libc_start_main (main=0x4149f2, argc=1, argv=0x7ffd4fce1858, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffd4fce1848) at ../csu/libc-start.c:291
#8  0x00000000004148a9 in ?? ()

だと何もわからない…

デバッグフラグ付きでコンパイルしないとこういうの全く見えないのかな,しかしクラッシュをステージング環境で見るのは初めてなので,再現できるかどうかわからない…

メインスレッドだとスレッド待ちしか無いのは当たり前かと思ってgdbで他のスレッドを見る方法を調べてみます.

(gdb) info thread
  Id   Target Id         Frame
* 1    Thread 0x7fc92f32d740 (LWP 18375) "application" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  2    Thread 0x7fc92930a700 (LWP 18407) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  3    Thread 0x7fc928b09700 (LWP 18408) "ghc_worker" 0x00007fc92d3a09d3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  4    Thread 0x7fc923fff700 (LWP 18409) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  5    Thread 0x7fc9237fe700 (LWP 18410) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  6    Thread 0x7fc922ffd700 (LWP 18411) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  7    Thread 0x7fc9227fc700 (LWP 18412) "ghc_worker" 0x00007fc92d3a09d3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  8    Thread 0x7fc921ffb700 (LWP 18413) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  9    Thread 0x7fc9217fa700 (LWP 18414) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  10   Thread 0x7fc920ff9700 (LWP 18415) "ghc_worker" 0x00007fc92d3a09d3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  11   Thread 0x7fc903bda700 (LWP 18438) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  12   Thread 0x7fc9033d9700 (LWP 18439) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  13   Thread 0x7fc902bd8700 (LWP 18440) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  14   Thread 0x7fc9023d7700 (LWP 18441) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  15   Thread 0x7fc901bd6700 (LWP 18446) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  16   Thread 0x7fc9013d5700 (LWP 18447) "ghc_worker" 0x00007fc92d39470d in poll () at ../sysdeps/unix/syscall-template.S:84
  17   Thread 0x7fc900bd4700 (LWP 18448) "ghc_worker" 0x00007fc92d3a09d3 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
  18   Thread 0x7fc8dffff700 (LWP 18455) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  19   Thread 0x7fc8df7fe700 (LWP 18468) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  20   Thread 0x7fc8deffd700 (LWP 18470) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  21   Thread 0x7fc8de7fc700 (LWP 18471) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  22   Thread 0x7fc8ddffb700 (LWP 18532) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  23   Thread 0x7fc8dd7fa700 (LWP 18533) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  24   Thread 0x7fc8dcff9700 (LWP 18534) "ghc_worker" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185

たくさんある,全部待ちになっていて意味が分からない…どのスレッドを見に行ってもwaitしてるかepoll_waitしてるかで,何故固まっているのか理解ができません.何もわからない.

これは…もしかしてデッドロックというやつなんじゃないだろうか,互いにwaitしているし…

yesodのアーキテクチャをあまり把握していないからどこでロックが生じているのか検討もつかない.せめてバックトレースが機能していれば把握の取っ掛かりになるんですが…というかghc_workerを見ても把握が出来ないのは当たり前ですね,これらはghcが生成したスレッド処理のためのスレッドですし.

詳しい人に相談してみたところ,やはりデッドロックに見えるそうで.

とりあえず何処で止まっているのか見えるようにコンパイルオプションを弄ろうかと思いましたが設定するべきコンパイルオプションがよくわからない.

いっそのこと-threadedを取り外してシングルスレッドで動かしておけばデッドロック起きないんじゃねーの,という案が自分の中から出てきました.とりあえず本番環境の-threadedを取り外してしまいました.とりはずしてもghc-workerが無くなってシングルスレッドになるだけで動くので,これで落ちなくなるなら暫くはこれで行くという案が採用されました.と思ったらstripeパッケージがRTS doesn't support multiple OS threads (use ghc -threaded when linking)というエラーを吐き出したので急遽元に戻しました.stripeが-threadedを前提に動かしているから外すことが出来ないのかな?

もしかしたら-threadedを有効にしていても,-with-rtsopts=-Nを外せばスレッドサポートを有効にしたまま普段動くスレッドを1つに抑えられるのではないかと思ったので,試してみます.

yesodのissueでdead lockとかで検索しても全然出てこないので,yesodデフォルトのコードに手を加えた結果なのかなあと再度不安になったので,stack newしたファイルを見て出来るだけデフォルトの設定に戻しました.(これにまた結構時間がかかった)

-with-rtsopts=-Nを削除しても-threadedが有効な限りスレッドは生成されるんですね…そりゃそうか,yesodが手動でスレッドを作っているわけで.

stack build --ghc-options='-g -debug'したらgdbで情報見れるようにならないかと期待してやってみます.

デバッグを有効にしたらアプリケーションがCPUを二倍ぐらい食うようになった気がする.いや,最適化をデフォルト状態にしたからか?

デバッグを有効にしてもgdbは??しか出さない,終わっている…

devを有効にしてログを見てみたらクラッシュする寸前にhttp応答を返さずに同じ部分へのSQLを数回発行していたからその部分のrunDBをまとめてみました,効果があるかは全くわかりません!