「db.fsyncUnlock()」コマンドが終了せずロックが開放されません

498 views
Skip to first unread message

norinomamedaifuku

unread,
Sep 9, 2014, 8:57:17 AM9/9/14
to mongo...@googlegroups.com
岸本です

お世話になります。
只今データベースファイルをバックアップすべく
データベースのロック→物理ファイル退避→アンロックの流れを試し、ツール作成など行っております。

コマンドの流れを試したところうまくいっていたのですが、
繰り返し実行しているうちに、ロック解除コマンド（db.fsyncUnlock()）がフリーズしたように終了しないケースが発生しました。（数度おきています）
その他ロック開放を妨げるような行為はないはずなのですが、なぜ終了しないのか理解できていません。

このような事態の場合、どういう状況になっているか、
またどのようにすれば起こさないことができるか、もしナレッジあればご教示いただけると助かります。
（ちなみに当方での本事象回避には、mongoサービスの再起動という手段を取っていますが、これでは運用に耐えれません。。）

mongoバージョンはlinux x64 2.6.3

参考情報としてロックしている時点のcurrentOp()は以下の通りです。
----------------------------------------------------------------------------------------
reptest:SECONDARY> db.currentOp()
{
        "inprog" : [
                {
                        "opid" : 892,
                        "active" : false,
                        "op" : "none",
                        "ns" : "",
                        "query" : {

                        },
                        "desc" : "repl writer worker 1",
                        "threadId" : "0x7feee2d8f700",
                        "waitingForLock" : false,
                        "numYields" : 0,
                        "lockStats" : {
                                "timeLockedMicros" : {
                                        "r" : NumberLong(0),
                                        "w" : NumberLong(466)
                                },
                                "timeAcquiringMicros" : {

                                }
                        }
                }
        ],
        "fsyncLock" : true,
        "info" : "use db.fsyncUnlock() to terminate the fsync write/snapshot lock"
}
----------------------------------------------------------------------------------------

また強制終了（ctrl+c）を行うと以下のログを吐き出します。

-----------------------------------------------------------------------------------------
^C2014-09-09T21:40:54.836+0900 Assertion failure isABSONObj() src/mongo/bson/bson-inl.h 183
2014-09-09T21:40:54.844+0900 0x864f81 0x813579 0x7f66ee 0x7ddacd 0x61a6a0 0x7f00485b5920 0x7f00492cc94a 0x823112 0x823149 0x823195 0x81b81c 0x81c6e6 0x81ccd1 0x66e7b5 0x69a06a 0x6647ca 0x67cdf4 0x7c1277 0x7a35e8 0x3cc4aec5a079
 /sb/mongodb/bin/mongo(_ZN5mongo15printStackTraceERSo+0x21) [0x864f81]
 /sb/mongodb/bin/mongo(_ZN5mongo10logContextEPKc+0x159) [0x813579]
 /sb/mongodb/bin/mongo(_ZN5mongo12verifyFailedEPKcS1_j+0x17e) [0x7f66ee]
 /sb/mongodb/bin/mongo(_ZNK5mongo11shell_utils18ConnectionRegistry30killOperationsOnAllConnectionsEb+0x40d) [0x7ddacd]
 /sb/mongodb/bin/mongo(_Z10quitNicelyi+0x40) [0x61a6a0]
 /lib64/libc.so.6(+0x32920) [0x7f00485b5920]
 /lib64/libpthread.so.0(recv+0x6a) [0x7f00492cc94a]
 /sb/mongodb/bin/mongo(_ZN5mongo6Socket5_recvEPci+0x22) [0x823112]
 /sb/mongodb/bin/mongo(_ZN5mongo6Socket11unsafe_recvEPci+0x9) [0x823149]
 /sb/mongodb/bin/mongo(_ZN5mongo6Socket4recvEPci+0x35) [0x823195]
 /sb/mongodb/bin/mongo(_ZN5mongo13MessagingPort4recvERNS_7MessageE+0x9c) [0x81b81c]
 /sb/mongodb/bin/mongo(_ZN5mongo13MessagingPort4recvERKNS_7MessageERS1_+0x36) [0x81c6e6]
 /sb/mongodb/bin/mongo(_ZN5mongo13MessagingPort4callERNS_7MessageES2_+0x31) [0x81ccd1]
 /sb/mongodb/bin/mongo(_ZN5mongo18DBClientConnection4callERNS_7MessageES2_bPSs+0x55) [0x66e7b5]
 /sb/mongodb/bin/mongo(_ZN5mongo14DBClientCursor4initEv+0xba) [0x69a06a]
 /sb/mongodb/bin/mongo(_ZN5mongo12DBClientBase5queryERKSsNS_5QueryEiiPKNS_7BSONObjEii+0xea) [0x6647ca]
 /sb/mongodb/bin/mongo(_ZN5mongo18DBClientConnection5queryERKSsNS_5QueryEiiPKNS_7BSONObjEii+0xa4) [0x67cdf4]
 /sb/mongodb/bin/mongo(_ZN5mongo9mongoFindEPNS_7V8ScopeERKN2v89ArgumentsE+0x387) [0x7c1277]
 /sb/mongodb/bin/mongo(_ZN5mongo7V8Scope10v8CallbackERKN2v89ArgumentsE+0xc8) [0x7a35e8]
 [0x3cc4aec5a079]
2014-09-09T21:40:54.845+0900 Error: assertion src/mongo/bson/bson-inl.h:183 at src/mongo/shell/query.js:81

-----------------------------------------------------------------------------------------

以上になります。

どなたかアドバイスいただければ幸いです。

よろしくお願いいたします。






Hiroaki Kubota

unread,
Sep 9, 2014, 10:17:47 AM9/9/14
to mongo...@googlegroups.com
窪田です。

環境やオペレーション、その他条件の詳細が無いので、あまりピンポイントではアドバイスできません。

まずスナップショットでのバックアップは、この条件が必要ですが把握しておりますか？
http://docs.mongodb.org/manual/core/backups/

中々敷居が高いのでお手軽に取るなら、hidden secondary を置いて、そこからmongodumpするのが一番安全です。
私はこの方法をお勧めします。

さて本題のロックモードの話ですが、どの位の時間ロックしているのでしょう？
DBのロックモードはMongoDBに限らず（oracleなどでも）相当短時間のロックを想定して作られています。
上記ドキュメントで触れているように瞬間的なスナップショットソリューションで取る必要があります。

db.fsyncUnlock() が帰って来ないバグ報告は以前から出ており
mongoシェルを２枚開いておいて、片方ハングしたら、もう片方から投げてみる。
などの方法があったりするのですが、なんにせよ細かい話は詳細がわかってからじゃないと意味がなさそうなので
追加情報を待ちます。









2014年9月9日 21:57 norinomamedaifuku <noriaki....@g.softbank.co.jp>:

--
このメールは Google グループのグループ「MongoDB JP」に登録しているユーザーに送られています。
このグループから退会し、グループからのメールの配信を停止するには mongodb-jp+...@googlegroups.com にメールを送信してください。
このグループに投稿するには mongo...@googlegroups.com にメールを送信してください。
http://groups.google.com/group/mongodb-jp からこのグループにアクセスしてください。
その他のオプションについては https://groups.google.com/d/optout にアクセスしてください。

norinomamedaifuku

unread,
Sep 9, 2014, 9:53:54 PM9/9/14
to mongo...@googlegroups.com
窪田さん

アドバイスありがとうございます
ブログもたくさん拝見させていただいておりこちらもありがとうございますｍ（＿＿）ｍ

現環境でsnapshotを用いることができないためOSのcpコマンドを用いています。
（恥ずかしながら英語は苦手ですが、snapshotが無い場合はcpコマンドでも可・・と読みました・・）

mongoの構成ですが
Primary-Secondary-Secondary（hidden/遅延同期）の3台構成にしています。
いずれのサーバもjourmal有効です。

バックアップの取得（lock/unLockの発行/およびcpコマンド対象）はこのhiddenデータベースよりとしています。
バックアップは最悪のケースのみを想定し、日次で1回バックアップを取れればよいかなというライトな感覚です。
（想像される通り極めてミッションクリティカルなシステムではありません）

> db.fsyncUnlock() が帰って来ないバグ報告は以前から出ており
そうなんですね。これは知りませんでした。

この方式の採用は、少し古いですがmongoのオライリー本をみて
mongodumpと物理ファイル退避の方法が記載されており後者の方がおすすめ？のような記載であったため採用した次第でした。

一般的に、といういい方は難しいかもしれませんが、mongodumpの方が採用も多くおすすめという感じでしょうか？

> さて本題のロックモードの話ですが、どの位の時間ロックしているのでしょう？
これ昨晩23時付近でロック開放できなくなってより今現在（よく朝10時）時点でまだ開放されていない状況です。なのでこのまま放っておいてもかえっては来ない・・と想像します。

またロック（db.fsyncLock()）→ロック開放（fsyncUnlock()）までの間隔は、
cpに数分掛けたケースもありますが、現在試験ではcpコマンドをスキップさせているため
ほぼ瞬時にロック開放要求を出しています。

またご案内いただいた通り、別のシェルからunLock要求を出すなどしてみたりした際、
うまく開放されたケースもあったのですが、できないこと（の方が）多く規則性など見いだせていませんでした。

文面とり散らかり申し訳ありません。
このような状況となります。

なにかお分かりでしたらコメントいただければ幸いです。

以上です
よろしくお願いいたします。




2014年9月9日火曜日 21時57分17秒 UTC+9 norinomamedaifuku:

Hiroaki Kubota

unread,
Sep 10, 2014, 4:44:22 AM9/10/14
to mongo...@googlegroups.com
なるほど、瞬時で解放できないのは辛いですね。
fsyncLockはbackground jobで、スレッドで処理されます。

ログにFSyncLockThread という名前の行が出ていると思うのですが、解放の成否でログに何か違いがありますか？

またunlockする前にdb.currentOp().fsyncLock を実行するとどうなりますか？
true が正常です。

同じく 直前に db.getLastError() で何か出てないですかね？



ソースコードを見るに、他のfsync系のジョブと混ざらない様にしているmutexがあるのですが
ちゃんと機能してるか判りません。

もし別のmongoshellで繋げられるなら、そっちからfsyncUnlockを投げまくると帰ってくるかもしれません。。。


2014年9月10日 10:53 norinomamedaifuku <noriaki....@g.softbank.co.jp>:

norinomamedaifuku

unread,
Sep 10, 2014, 5:05:16 AM9/10/14
to mongo...@googlegroups.com
窪田さん

ご教示ありがとうございます。
コメント非常に助かります。

ログにFSyncLockThread という名前の行が出ていると思うのですが、解放の成否でログに何か違いがありますか？
何度もロック＆開放を試したはずですがログレベルの問題か、1件のみしか同スレッドのログを見つけられませんでした
2014-09-09T22:05:12.592+0900 [FSyncLockThread] BackgroundJob starting: FSyncLockThread
（一時のみログレベルを変えたためその時のものなのでしょうかね。）

unlock直前の挙動については、いただいた情報で少々試してみます。
（まずはフリーズ状態を再現してみます・・・・・＾＾；）

よろしくお願いいたします

岸本



2014年9月10日水曜日 17時44分22秒 UTC+9 crumbjp:

norinomamedaifuku

unread,
Sep 10, 2014, 6:37:27 AM9/10/14
to mongo...@googlegroups.com
窪田さん
皆様

少し進展しました。
ロックフリーズを再現させる？手段がわかった気がします。

Lockコマンドのネスト発行に問題がありそうです。

バックアップツールのためシェルスクリプト(bash)を作成しその中でコマンドを発行していましたが
その背後で別のmongoクライアントを立ち上げ、ロックを発行のまま放置した状態で
バックアップシェルを実行すると、結構な確率でアンロックがフリーズしました（ちょっとまだ検証不完全）。

そもそもlockメカニズムがよく理解できていないのかもしれません。。。

・ロック（db.fsynckLock()）を発行するプロセスとロック解放（db.fsyncUnlock()）を発行するプロセス（スレッドかな）は別々でも問題ないのか。
・ロック中にさらにロックコマンドを発行すると「"ok":1」が帰ってくるが、ロックスレッドは1つしか見えない。ロックが上書きされるのか、ネストする仕様か。

もう1つ自分の処理でロックがらみの地雷を踏みそうなポイントがありました。
バックアップツールでは、以下の記載でコマンドを発行しています。

※抜粋
CMD_LOCK="db.fsyncLock()"
CMD_UNLOCK="db.fsyncUnlock()"

/usr/local/mongodb/bin/mongo --host $hostName $targetDB --eval "printjson($CMD_LOCK)" --quiet -u $user -p $pass --authenticationDatabase $authDB 
/usr/ocal/mongodb/bin/mongo --host $hostName $targetDB --eval "printjson($CMD_LOCK)" --quiet -u $user -p $pass --authenticationDatabase $authDB 

evalオプションを用いていますが、db.evalなどマニュアルを見る限りwriteLockをかけるとのこと。
なんか我ながら怪しいなぁと思う次第です。

以上です。
引き続き動作させてみます。












2014年9月10日水曜日 18時05分16秒 UTC+9 norinomamedaifuku:

norinomamedaifuku

unread,
Sep 10, 2014, 7:40:40 AM9/10/14
to mongo...@googlegroups.com
たびたびです。

単一のmongoシェルクライアントを用いて
以下のようなコマンド発行を試してみました。
自環境では確実にフリーズしました。

①ロック＆解除1回づつ
db.fsyncLock()
db.fsyncUnlock()
当然ながら問題なく終了。

②ロック＆解除2回づつ
db.fsyncLock()
db.fsyncLock()
db.fsyncUnlock()　←ロック解除OK
db.fsyncUnlock()　←ロック解除OK
これも正常終了するが、なぜ解除が2度ともOKとなるのか。。

③ロック＆解除3回づつ
db.fsyncLock()
db.fsyncLock()
db.fsyncLock()
db.fsyncUnlock()
db.fsyncUnlock()　←ここでフリーズ（というよりデッドロックのような感じでしょうか）　以降の操作不可　
db.fsyncUnlock()

複数のロックが発行された場合の挙動がどうにもおかしい感じでしょうか。
（オペレーションもおかしいですけどね。。。）

以上です
引き続き試してみます。



///////////////////////////////////////////////////////////////以下実行ログ
  db.currentOp()
{
        "inprog" : [
                {
                        "opid" : 37,
                        "active" : false,
                        "op" : "none",
                        "ns" : "",
                        "query" : {

                        },
                        "desc" : "repl writer worker 1",
                        "threadId" : "0x7f8ee46cb700",
                        "waitingForLock" : false,
                        "numYields" : 0,
                        "lockStats" : {
                                "timeLockedMicros" : {
                                        "r" : NumberLong(0),
                                        "w" : NumberLong(251)
                                },
                                "timeAcquiringMicros" : {

                                }
                        }
                }
        ]
}
>
>
>
>
■1回づつ
> db.fsyncLock()
{
        "info" : "now locked against writes, use db.fsyncUnlock() to unlock",
        "ok" : 1
}
> db.fsyncUnlock()
{ "ok" : 1, "info" : "unlock completed" }

■2回づつ
> db.fsyncLock()
{
        "info" : "now locked against writes, use db.fsyncUnlock() to unlock",
        "ok" : 1
}
> db.fsyncLock()
{
        "info" : "now locked against writes, use db.fsyncUnlock() to unlock",
        "ok" : 1
}
> db.fsyncUnlock()　・・開放OK
{ "ok" : 1, "info" : "unlock completed" }
> db.fsyncUnlock()　・・開放OK（ロックは２つ存在するということか？）
{ "ok" : 1, "info" : "unlock completed" }
> db.fsyncUnlock()　・・開放NG（ここでNGが戻されるということは数勘定的にはあっているが・・・・そういうものなのか？）
{ "ok" : 0, "errmsg" : "not locked" }

■3回づつ（ここでフリーズします）
> db.fsyncLock()
{
        "info" : "now locked against writes, use db.fsyncUnlock() to unlock",
        "ok" : 1
}
> db.fsyncLock()
{
        "info" : "now locked against writes, use db.fsyncUnlock() to unlock",
        "ok" : 1
}
> db.fsyncLock()
{
        "info" : "now locked against writes, use db.fsyncUnlock() to unlock",
        "ok" : 1
}
> db.fsyncUnlock()　・・1つ目？のロックは開放された模様
{ "ok" : 1, "info" : "unlock completed" }
> db.fsyncUnlock()　・・ここでフリーズ（以降コマンド発行不可）




2014年9月9日火曜日 21時57分17秒 UTC+9 norinomamedaifuku:

Hiroaki Kubota

unread,
Sep 11, 2014, 9:48:09 AM9/11/14
to mongo...@googlegroups.com
窪田です。
残念ながら再現しましたね。
どうやらFSyncスレッドでロックしています。
FSyncLock は他のジョブをブロックして処理するのですが、どうやら入るべきmutex_cond が誰かに吸われてるようです。

３回fsyncLock しても、暇なmongodならば、別ターミナルからfsyncUnlockを投げまくれば回復するケースもあるようですが
１度その状態になってしまうと、もう一回fsyncLockした状態でも、unlockで詰まるようですね。

正確にはdb.fsyncLock() を多重にかけてしまうと、そこからおかしくなります。
別のターミナルからロックしても同じくダメですね。

workaround としては、db.fsyncLock()は同時に掛けないようにする。
です。

バグ報告すべきですが、どうしますか？
私から報告しても良いですけれども。





2014年9月10日 20:40 norinomamedaifuku <noriaki....@g.softbank.co.jp>:

Hiroaki Kubota

unread,
Sep 11, 2014, 10:07:51 AM9/11/14
to mongo...@googlegroups.com
しっかりバグ報告を調べてみましたが、完全に一致するものがありました。
https://jira.mongodb.org/browse/SERVER-6302?jql=issuetype%20%3D%20Bug%20AND%20text%20~%20fsyncUnlock%20ORDER%20BY%20created%20DESC
随分と古くからあるのですね。。

ワークアラウンドもありますが、他人のかけたロックは当然他人が開放する可能性があるので微妙ですね。。。
Fix 2.7Desired とはなんとものんびりした話です。。。

（コメントでブチギレておきました）

2014年9月11日 22:48 Hiroaki Kubota <cat.s...@gmail.com>:

norinomamedaifuku

unread,
Sep 11, 2014, 10:09:26 AM9/11/14
to mongo...@googlegroups.com
窪田さん！

調査いただきありがとうございます。
非常に勉強になります。

当方のレベルでは到底できる調査ではありませんでした。
事象が再現されそれがバグでいうことであれば非常に納得な内容です。
本当にありがとうございます。

バグ報告すべきですが、どうしますか？
こちら自分では細かな説明ができませんのでお手数ですがお願いできますでしょうか。

workaround としては、db.fsyncLock()は同時に掛けないようにする。
こちらもそうですね。
少なくともfsyncLockが掛かっている場合には、
必ずdb.currentOp().fsyncLockはtrueを返しましたので、
trueを返す限りは同時にロックを発行させないように制御を入れました。
（発生はツール試験中でしたので変に2重ロックを掛けてしまっていた可能性も高そうでした）

ちなみにバックアップの方式ですが、mongodumpへの切り替えも視野にいれつつ
上記制御を入れたファイルコピー方式でしばらく運用してみようと思います。

このたびはお時間かけていただき、本当にありがとうございました。
感謝いたします。

引き続きよろしくお願いいたします。

岸本


2014年9月9日火曜日 21時57分17秒 UTC+9 norinomamedaifuku:

norinomamedaifuku

unread,
Sep 11, 2014, 10:12:20 AM9/11/14
to mongo...@googlegroups.com
入れ違いでした！！

バグ報告済みだったのですね。。
確かに微妙すぎる仕様。。

ですがバグならバグでスッキリします＾＾
ブチギレにも感謝ですｗｗ

本当にありがとうございました。

ｍ（＿＿）ｍ



2014年9月11日木曜日 23時07分51秒 UTC+9 crumbjp:
Reply all
Reply to author
Forward
0 new messages