ghciでforkして見てみたらBlockedOnMVarが発生してるのでやはりデッドロックっぽい

ghciでYesodアプリケーションを動かしてみます.

getApplicationReplがあるのでこれを使います.

(port, foundation, app) <- getApplicationRepl
t <- fork $ runSettings (warpSettings foundation) app

と言った感じでYesodアプリケーションををghciで別スレッドで動かせます.

さっそくクラッシュしました.

クラッシュしたのは良いけれどご飯食べるから暫く放置してたら

GET /favicon.ico
  Accept: image/webp,image/apng,image/*,*/*;q=0.8
  Status: 200 OK 0.000318s
GET /robots.txt
  Accept: */*
  Status: 200 OK 0.000223s

が出てきて驚愕しました. なんでfaviconとrobotsへのアクセスが成功しているんだ…? と思ってstatic以下のファイルにアクセスしてみたらアクセスが成功しました.

他にアクセスできるrouteはあるだろうかと思って探査してみましたが存在せず.

この状況をどう見るべきか.

もともとデータベースを全く利用していないtry-pandoc-with-fileでも同じような応答なし状態になることはあったので, データベースの問題ではないと思っていました. しかし, defalutLayoutでrunDBを実行しているので, defaultLayoutによる問題ならデータベースへのアクセスで詰まっているのかもしれません. しかし, データベースへのアクセスで詰まる原因が全くわかりません. insertなどのロックに関わる処理を行っているならまだしも, 行っているのはselectだけであることがログからも明白です.

とりあえず外から見るだけで状況をこれ以上見るのは難しいだろうと判断してスレッドの状況を調べてみようと思いました.

*Application Control.Concurrent GHC.Conc> threadStatus t
ThreadBlocked BlockedOnMVar

やっぱりメッセージパッシングでブロックしてますね… なんとなくそんな気はしていました. しかし, 私はYesodフレームワークを使っているので, 自分でMVarなどを生成してはいないので, どこで何がブロックしてるのか全くわからない. Yesodのソースコード見てもtakeMVarを使ってる部分1つだけだし終了シグナルを待つ時にしか使ってないし何処で使ってるのか全くわからない. Yesodも何らかのライブラリを使っているから抽象化されているとかなんですかね.

せめてスレッドが何処のコードでブロックしているのか知れればあたりがつけやすいんですが, そういう情報ghciで見れないんでしょうか? (非同期例外を投げればスタックトレースが見れるという指摘あり)

persistentがブロックしているのかと思ってコードを見てみましたがMVarは使ってませんね.

foreign-storeを追加してまでstack ghciで動しているのにeventlogは出力されない. リンカオプションで出力するように設定しているはずなのに何故? と思ったけどghciならリンカオプションは無視するのかな… メインスレッドがデッドロックしてしまうとeventlog自体が生成されなくなるため出力する方法がわからない.

PGPOOLSIZEを増やしてみたらクラッシュしなくなりました

調査方法がわからないのでデータベースアクセスがネックになってるならPGPOOLSIZEを増やせば良いんじゃねと思い10から100に増やしてみました. いや, MVarでデッドロックになっているならこんなことをしても無駄だと思うんですけど… おい, デッドロックしなくなったぞ, マジか.

本番環境にも同じ設定書いておいてクラッシュしなくなるか観察します.

しかし, この方法でのクラッシュ回避は, 単に数値を増やしただけのため, アクセスが増量すればすぐクラッシュすることが予想できます. 本来は根本的な解決をしなければいけません.