Kouhei Sutou
kou****@clear*****
2016年 11月 24日 (木) 18:29:48 JST
須藤です。 情報提供ありがとうございます。 念のため、1つめのケースも2つめのケースもどちらともクラッシュ した形跡がないか追加で確認してもらえないでしょうか？ クラッシュしていた場合はPostgreSQLのログまたはWindowsのログ （イベントビューアで見れるログ）に記録が残っていると思います。 記録が残っていた場合はすべてがムリだとしても少なくとも発生時 刻を提供してもらえると助かります。 もしクラッシュしていた場合は、クラッシュしたことにより GroongaのDB内にロックが残っていることが原因の可能性が高いで す。このケースの場合は、クラッシュの原因を調査することにより、 再発を防ぐのがよいかと思っています。 （なお、ウイルススキャンソフトなど外部のアプリケーションが GroongaのDBのロックをとることはありません。GroongaのDBのロッ クはOSが提供しているファイルロックなどの仕組みではなく Groonga内で実装しているロックのため、外部のアプリケーション はロックをとる手段を知らないからです。） 以下は、クラッシュしていない場合の話です。 1つめのケースではインデックスが壊れています。 > 2016-11-11 18:09:44.432000|C| [ii][buffer][put] loop is found: <Lexicon16912_0.index> :(2218:1)->(14:1) というログがそれを表しています。 クラッシュしていないのにこの状況になるならGroongaのインデッ クス更新ロジックに問題があると思います。 取得してもらったcolumn_listの結果では、ロックを獲得できてい ないインデックスはLexicon16916_0.indexでした。 > [389,"index","base/16384/pgrn.0000185","index","COLUMN_INDEX|WITH_POSITION|PERSISTENT","Lexicon16916_0","Sources16916",["Sources16916.lower"]] しかし、「loop is found」のログではLexicon16912_0.indexで問 題が発生しています。そのため、ロックがとれないこととインデッ クスが壊れていることは関係がない可能性が高いです。 森さん、[groonga-dev,04180]に添付されているログに「loop is found」が発生したときのバッファーのダンプも含まれているので すが、なにか気になるところはないでしょうか？ https://ja.osdn.net/projects/groonga/lists/archive/dev/2016-November/004183.html 2016-11-11 18:09:44.437000|d| 37986=(37939:37976),(2221:1) 2016-11-11 18:09:44.437000|d| 37976=(1026:8136),(14:1) でridが2221の後にridが14になっているのがおかしいのです。 （クラッシュしているのならおかしくなってもしょうがないですが、 もしクラッシュしていなかったらGroongaに問題がある気がします。） なお、更新を続けたらエラーが発生しなくなったということですが、 おそらく、インデックスの特定の箇所だけがおかしくなっており、 そのあたりを更新しているときはエラーが発生し、そこを触ってい ないときはエラーが発生しないという感じかと思います。 REINDEXをすることで解消すると思いますが、クラッシュが原因で ない場合は再発の可能性があります。 1つめのケースと2つめのケースで共通のbase/16384/pgrn.0000XXX のロックに関するエラーですが、複数の接続で同時に更新していな いのであれば、ロックが残留していると考えられます。ロックが残 留する理由はクラッシュが一番可能性が高いです。 もし、複数の接続で同時に更新していて、更新が激しいなら単にタ イムアウト時間が短く、他の接続でロックを獲得できていないだけ かもしれません。この場合は、更新を抑える・1つの接続だけから 更新する・I/O性能のよいディスクに変える・タイムアウト時間を もう少し長くする、というのが対策になります。 2つめのケースにだけあるbase/16384/pgrnのロックに関するエラー も、クラッシュによりロックが残留している可能性が一番高いです。 クラッシュしていない場合は最新のPGroongaに更新することで解消 される可能性があります。少し前のPGroongaでは接続終了時に必要 以上に該当ファイルのロックをとるようになっていました。そのた め、接続終了が重なるとなかなかロックを獲得できないことがあり ました。 接続終了（ログで言えばgrn_fin()）の直前に該当ログがでている ことが多いのでこのタイミングの可能性は高そうです。が、特に接 続終了が重なっているわけでもないので、クラッシュでロックが残 留している可能性が高い気はします。 2016-11-21 14:44:08.158000|n| io(base/16384/pgrn) collisions(31000/65): lock failed 1000 times 2016-11-21 14:45:03.517000|w| [DB Locked] time out(30000): io(base/16384/pgrn) collisions(120000/67) 2016-11-21 14:45:03.614000|n| (3 same messages are truncated) 2016-11-21 14:45:03.619000|n| grn_fin (0) ということで、まずはクラッシュした痕跡がないか確認してみても らえないでしょうか？ -- 須藤 功平 <kou****@clear*****> 株式会社クリアコード <http://www.clear-code.com/> Groongaベースの全文検索システムを総合サポート： http://groonga.org/ja/support/ パッチ採用 - プログラミングが楽しい人向けの採用プロセス： http://www.clear-code.com/recruitment/ OSS開発支援サービス: http://www.clear-code.com/blog/2016/6/27.html
