高見 直輝
takam****@orega*****
2016年 11月 25日 (金) 12:25:48 JST
お世話になります。高見です。 まず、全てのケースについて、PostgreSQLがクラッシュした形跡は在りませんでした。 ただ、いずれも直前にOSのシャットダウンが行われており、そのときに以下のログが確認できました。 ※日時は２つ目のケースのものです ・シャットダウン時（2016/11/18 18:28:23） terminating connection due to administrator command ・起動時（2016/11/19 13:43:34） pg_ctl: 他のサーバが動作中の可能性がありますが、とにかくpostmasterの起動を試みます。 以後、PGROONGAへのインデックス追加でエラーとなる。（PGROONGAを使わないテーブルへの追加は問題無し） OSのシャットダウンでもクラッシュと同等の状態になる可能性はありますでしょうか？ 前後の流れから、OSのシャットダウン時にPostgreSQLのプロセスが強制終了されている可能性があります。 ※通常の停止処理では出力されるログが、出力されていなかった。 前回の内容に関して、何点か確認させて下さい。 ・クラッシュが原因の場合、ファイルに保存されているデータが破損しているという認識で良いのか？ →“ロックが残る”という状態とインデックス破損の違いがよくわかりません。 ・現在予想されている原因と回復方法の組み合わせは、以下のもので間違いないか？ クラッシュ：インデックス再構築 インデックス破損：インデックス再構築 ロック負荷：負荷の低減（PGROONGAを現行最新版へバージョンアップ） ・ロックを必要以上に取得する『少し前のPGroonga』はバージョン1.0.3以後か？ →1.0.3から1.1.3にアップデートしてからこの問題が頻発しているように感じています。 負荷増加が1.0.3以後の話であれば、これが原因の可能性が高いと言えませんか？ 以上、よろしくお願いします。 > 須藤です。 > > 情報提供ありがとうございます。 > > 念のため、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) > > > ということで、まずはクラッシュした痕跡がないか確認してみても > らえないでしょうか？ ----------------------------- 高見 直輝 <takam****@orega*****> 株式会社オレガ TEL:03-3267-0150 FAX:03-3267-0180
