MongoDBの新機能：ジャーナリングについて詳しく

v1.8でMongoDBはジャーナリングと呼ばれる機能が新たに加わりました。今日はMongoDBのジャーナリングについて、実際にどのような処理が行われているのかを確認しながら、丁寧に見ていくことにしましょう。※なお、ジャーナリングという言葉自身、Mongoにこの機能が実装されるまで深く意識するようなことはありませんでした。解釈の部分で誤りなどがあるかもしれません、その際はご指摘していただけると幸いです。

ジャーナリングによってデータの堅牢性が格段に高まった

v1.8でジャーナリング機能が追加されたことによって、シングルサーバーにおけるデータの堅牢性がさらに高まりました。ジャーナリングという言葉は主にファイルシステムの分野においてかなり前から議論され、改善が進められてきた機能です。この意味におけるジャーナリングの目的はファイルシステム全体を保護することであり、そのためにメタデータの整合性を保持するために処理が施されるのが一般的なものです。一方、データベースで用いられるジャーナリングの目的は主にデータの保全であり、サーバーの障害からデータの損失をいかに最小限に抑えられるか、という目的で処理が施されます。もちろんMongoDBにおけるジャーナリングの目的も後者に該当します。

また、サーバーが完全に再起不能な状態に陥ってしまう状況に備えたデータ保全対策も重要で、その場合の対策は物理的に異なるサーバーにReplica Setを（またはMaster/Slave）構成するといった事が必要です。MongoDBでは従来のReplica Setによるデータ保全に加えて、ジャーナリング機能が今回新たに加わった形でシングルサーバーに対しての強力なデータ保全機能が備わりました。これによりサーバーダウンによるデータの損失を最小限にとどめることができ、またスムーズなリカバリが可能になりました。

実はジャーナリングが導入される前のバージョンまでは、シングルサーバーに対してはそれほど強力なデータの保全機能を備えているわけではありませんでした。次の章では、まずジャーナリングが追加される前のv1.6が抱えていた問題点を指摘し、それがジャーナリングによってどのように改善されるのかを示すことにします。

insertなどのデータ変更のディスクへの反映は60秒に1回

MongoDBを使用する多くの場合、各種言語ドライバを介してMongoDBへデータ処理を行うはずです。その際に注意して欲しいのは、多くのドライバのデータのinsertは"fire-and-forget"と呼ばれ、毎回のinsert実行後、それが実際にディスクに書き込まれたかを確認せずに次の処理を次々に実行します。基本的にはupdate等のクエリに対しても同じです、これらのオペレーション併せて「データ変更処理」と呼ぶことにします。
この理由の1つに、MongoDBではinsert処理実行後すぐにデータがディスクに書き込まれるわけではないというのが挙げられます。まずはメモリに書き込まれ、（デフォルトでは）60秒に1回、メモリ上の全てのデータがディスクに書き込まれるという処理が行われています。これによって大量のデータを効率良くかつ高速に書き込めるようになっているのですが、これはメモリからディスクへの書き込みが行われる前にサーバーのダウンなどの何らかの問題が生じた場合にはまだディスクに書き込まれていなかったデータは完全に消失することになってしまうというデメリットも持っています。つまりデフォルトでは最悪60秒の間にinsertされたデータが丸々失われてしまうリスクを背負っていることになります。
ただ、この問題への対応策は既に2点用意されています。
1つは起動時のコマンドラインオプション"--syncdelay"によってディスクへのフラッシュ間隔を任意の秒数に変更することです。ただしこの設定を短い秒数に変更することで、Replica SetsやMaster/Slave環境を構成している場合はメンバーとの同期のための通信量が増えてしまい、大きな負荷となりえます。シングルサーバーで稼働している場合以外にはこの値を減少させることは推奨されていません。
2つ目は毎回のinsertの実行結果を確認するオプションがドライバに備わっているはず（"safe"モード、または "set write concern"と呼ばれているコマンドです。）ですのでそれを使用する事です。このオプションを使用する事で、毎回のinsert()コマンドの後にgetLastError()コマンドを実行するようになります。このgetLastError()コマンドは、直前のオペレーションが成功したか否かを確認するコマンドです。またこのコマンドを実行することでデータに変更が加えられるオペレーションに対しては即座にディスクに書き込まれるようになります。ただしこのモードを使用すると（当たり前ですが）明らかに処理速度が低下します。MongoDBを利用する際には"critical"なデータと"non-critical"なデータという区別を持ち続け、それに併せた適切なデータ変更処理を行うようにしてください。

以上をまとめますと、MongoDBのデフォルトの振る舞いは"non-critical"なデータを想定したパフォーマンス重視に触れた設定になっています。安全なデータ変更処理を行う場合は、パフォーマンスを多少犠牲にしてでも上に述べた2つの施策（特に後者）を必ず行うようにして下さい。

ジャーナリングがデータの保全性を格段に高める第3の手段を与えてくれた

そしてv1.8で第3の手段となるジャーナリング機能によって、先ほど述べたデータ損失のリスクを大幅に低減されることになりました。
ジャーナリング機能を有効にして起動されたMongoDBは、実際にオペレーションを実行してデータに変更が加えられる前にこのオペレーション自身を追記専用の先行書き込みログ、ジャーナルファイルという特殊なファイルに書き込みます。より厳密に言えば100ミリ秒に1回、グループコミットという手法を用いてジャーナルファイルにオペレーションを書き込んでいきます。
このジャーナルファイルへの先行書き込みによって、インデックス作成などのデータの変更処理の実行途中、あるいはいくつかのデータがディスクにフラッシュされていない状況でサーバーがダウンしてしまったとしても、再起動時にそのオペレーションを再実行することでデータのリカバリができるようになります。ジャーナル機能をオンにしたMongoDBでは再起動時にクライアントから処理を受け付ける状態に入る前に、ジャーナルファイルに記録されたオペレーションを再実行してデータのリカバリが行うようになります。これによって今まで最悪60秒間のデータが全て失われてしまう可能性のあったものが、100ミリ秒間のデータの損失のみで済むようになりました。また、今まで必要だったmongod.lockの削除と、起動後のdb.repairDatabase()の実行も不要になりました。
このようにジャーナリングはデータの保全性に対して非常に大きな改善をもたらしてくれました。ただし、毎回データに変更を与えるオペレーションが先行してログに書き込まれる事になるので、それなりにパフォーマンスが落ちてしまう事はさけられません。記事、MongoDB Journaling Performance - Single Server Durabilityでは、ジャーナリングによって30%程度パフォーマンスが落ちてしまったという報告がされています。まだこの機能が登場して間もないことやこのようなパフォーマンスの問題もあり、v1.8においてはジャーナリングはデフォルトの機能にはなりませんでした。jounalingを使用するかどうかは、MongoDBをどのような目的や環境で利用しているかによって判断すべきでしょう。ただし今後ジャーナリングのグループコミットを行う間隔の改善や種々のパフォーマンスの改善がある程度進んだ段階でデフォルトの機能になる事でしょう。

従来のダウンからの復帰に必要な手順

さて、実際にジャーナリングの振る舞いを確認する前に、先ほど触れた言葉、mongod.lock、db.repairDatabase()に関する従来のサーバーダウンから復帰の手順についてお話ししておきます。
mongodが正常に終了されなかった場合、手動で再起動して正常な状態に復帰させるには以下の2つの手順が必要になってきます：

起動前に mongod.lock ファイルを削除する

mongodの起動時にはデータディレクトリの中にはmongod.lockというファイルが作成されます。また、正常終了時にはこのファイルは削除されます。mongod.lockの主な役割は正常終了されたか否かをファイルの存在によって確認することと、1つのデータディレクトリに1つのmongodしかアクセスできないようにブロックする役割です。異常終了の場合はこのファイルが残ることになり、再起動する場合には警告が出てこのファイルを削除しない限り起動することができません。この手順の詳細は後ほど具体的に説明しますのでここでは割愛させて頂きます。

起動後、db.repairDatabase()を実行して全データが壊れていないかのチェックを行う

また、いくつかのデータが破損している可能性がありますので起動後はまずdb.repairDatabase()というコマンドを実行して全データのスキャンを行う必要があります。このdb.repairDatabase()コマンドは全データが壊れていないかを確認するとともにデフラグのような役割も担います。ただ、このコマンドはデータベースの規模が大きいと（ロックはしないものの）パフォーマンスの大幅な低下と、非常に時間がかかってしまう事には注意しないといけません。また、実行のためにテンポラリファイルをdbpath内に新たに作成することを知っておかないといけません。

実際にジャーナリングの動作を確認してみる

それではここからは実際に手を動かし、mondodのサーバーログを確認しながらジャーナリングの動作に対する理解を深めることにしましょう。

journalサブディレクトリが作成され、ジャーナルファイルが作成されていることを確認する

mongodの起動時に--journalオプションをつけて起動してみましょう、ここではdbpathはdataディレクトリを指定しています。そして早速mongodのサーバーログを確認してみましょう。[1]で"journal dir=data/journal" として、なにやら新しいディレクトリがdbpath以下に作成されたのがわかります。[2]では"recover : no journal files present, no recovery needed"と書かれていますね。"recover"を行おうとしたけれども、ジャーナルファイルが見つからなかったのでその必要がない事が書かれています。その後、[3]でmongodはクライアントからの接続待ちの状態になります。（今回は必要な部分しか抜粋していません。）

$ mongod --journal --dbpath data
Sun Jun  5 22:33:13 [initandlisten] MongoDB starting : pid=50557 port=27017 dbpath=data 64-bit
Sun Jun  5 22:33:13 [initandlisten] db version v1.8.0, pdfile version 4.5
[1]Sun Jun  5 22:33:13 [initandlisten] journal dir=data/journal
[2]Sun Jun  5 22:33:13 [initandlisten] recover : no journal files present, no recovery needed
[3]Sun Jun  5 22:33:13 [initandlisten] waiting for connections on port 27017
Sun Jun  5 22:33:13 [websvr] web admin interface listening on port 28017
...

まず[1]で実際にdbpathにjournalサブディレクトリが作成された事を確認してみましょう：

$ ls data   
journal    mongod.lock    test.0    test.1    test.ns

確かに作成されていることが確認できました。さらにjournalサブディレクトリの中を確認してみます：

$ ls -lh data/journal/

total 24
-rw-------  1 doryokujin  staff   8.0K  6  5 22:55 j._0
-rw-------  1 doryokujin  staff    88B  6  5 22:56 lsn

j._0 というファイルとlsnというファイルが作成されているのがわかります。どちらもバイナリファイルですので中身を確認することはできません。それではここでtestデータベースのmycollコレクションに対して100,000件の挿入を行ってみます：

$ mongo localhost:27017/test  #<host>:<port>/<dbname>

> for(var n=0; n<100000; n++){ db.mycoll.insert( { "n": n } ); }

ここでもう一度journalサブディレクトリを確認してみます：

$ ls -lh data/journal/

total 23696
-rw-------  1 doryokujin  staff    12M  6  5 23:19 j._0
-rw-------  1 doryokujin  staff    88B  6  5 23:19 lsn

j._0ファイルサイズが増えているのが確認できました。この j._0ファイルは前述したジャーナルファイルと呼ばれるもので、データに対して更新が行われた際のオペレーションが全て記録されています。インデックスの作成もジャーナルファイルに記録されます：

> db.mycoll.ensureIndex({"n":1})

このオペレーションに対してもジャーナルファイルに記録されているのが確認できます：

$ ls -lh data/journal/

total 30280
-rw-------  1 doryokujin  staff    15M  6  5 23:29 j._0
-rw-------  1 doryokujin  staff    88B  6  5 23:29 lsn

ジャーナルファイルはそのファイルサイズが1GBに達した時点でローテートされj._0, j._1,...という名前で保存されていきます。また、古くなったジャーナルファイルは自然に削除されるため、通常運用においては2つから3つのジャーナルファイルが存在している状況になります。ただし、念のためにジャーナルファイル用に10GB程度の空き容量を確保するようにしておいて下さい。また、データの読み取りに関するオペレーションは何回行ってもジャーナルファイルには記述されません：

> var ary=[]; 
> for(var n=0; n<1000; n++){ ary[n]=db.mycoll.findOne( { "n": n } ); }
> ary

[
        {
                "_id" : ObjectId("4deb904e79d55a3e071f21a9"),
                "n" : 0
        },
        {
                "_id" : ObjectId("4deb904e79d55a3e071f21aa"),
                "n" : 1
        },
...

$ ls -lh data/journal/

total 30280
-rw-------  1 doryokujin  staff    15M  6  5 23:29 j._0
-rw-------  1 doryokujin  staff    88B  6  5 23:37 lsn

正常終了時から再起動までの動作を確認する

ここからはmongodの正常終了・異常終了の際のジャーナリング機能周辺の挙動を確認してみることにしましょう。まずは正常終了させるために、起動している27017のmondodに対してCTRL+Cを押します。するとmongodのサーバーログは正常に終了処理を開始します。[1]に"shutdown: journalCleanup..."という表示が出ていますね、ここでジャーナルファイルのクリーンアップが行われているようです。[2]でジャーナルファイルが削除されているのが確認できます。[3]でmongod.lockファイルが削除され、[4]で正常な終了処理が完了したという通知とともに、mongodサーバーが終了します。

...
Sun Jun  5 22:45:30 [interruptThread] shutdown: closing all files...
Sun Jun  5 22:45:30 closeAllFiles() finished
[1]Sun Jun  5 22:45:30 [interruptThread] shutdown: journalCleanup...
[2]Sun Jun  5 22:45:30 [interruptThread] removeJournalFiles
[3]Sun Jun  5 22:45:30 [interruptThread] shutdown: removing fs lock...
[4]Sun Jun  5 22:45:30 dbexit: really exiting now

このように、正常な終了処理が行われるとjournalサブディレクト内のジャーナルファイルは全て削除されます。正常に終了したのですから、終了前の全てのデータ変更オペレーションはディスクに反映されていることが保証されていますので、次の起動の際にジャーナルファイルを保存しておく必要もないわけです。

異常終了時から再起動までの動作を確認する（ジャーナリング機能を有効にしていない場合）

それではここでmongodを意図的に異常終了（ダウン）させてみますが、ここではさらにジャーナリング機能を有効にした場合とそうでない場合でその挙動の違いを確認することにします。まずは--journalオプションなしで起動し、newcollコレクションに対して100,000件のデータ挿入してみましょう。

$ mongod --dbpath data

> for(var n=0; n<100000; n++){ db.newcoll.insert( { "n": n } ); }

この操作の後にmongodを強制的にシャットダウンさせます。

$  ps aux | grep mongod | grep -v grep
doryokujin 35401  16.4  0.5  2675212  22240 s015  S+   11:54PM   0:00.61 mongod --dbpath data

$  sudo kill -KILL 35401

強制終了されたmongodに対して再起動しようとすると前述したとおり、以下の様な警告が出て起動できません。

mongod --dbpath data
Sun Jun  5 23:56:48 [initandlisten] MongoDB starting : pid=42647 port=27017 dbpath=data 64-bit 
Sun Jun  5 23:56:48 [initandlisten] db version v1.8.0, pdfile version 4.5
Sun Jun  5 23:56:48 [initandlisten] git version: 9c28b1d608df0ed6ebe791f63682370082da41c0
Sun Jun  5 23:56:48 [initandlisten] build sys info: Darwin erh2.10gen.cc 9.6.0 Darwin Kernel Version 9.6.0: Mon Nov 24 17:37:00 PST 2008; root:xnu-1228.9.59~1/RELEASE_I386 i386 BOOST_LIB_VERSION=1_40
************** 
[1]old lock file: data/mongod.lock.  probably means unclean shutdown
[2]recommend removing file and running --repair
see: http://dochub.mongodb.org/core/repair for more information
*************
Sun Jun  5 23:56:48 [initandlisten] exception in initAndListen std::exception: old lock file, terminating
Sun Jun  5 23:56:48 dbexit: 
Sun Jun  5 23:56:48 [initandlisten] shutdown: going to close listening sockets...
Sun Jun  5 23:56:48 [initandlisten] shutdown: going to flush diaglog...
Sun Jun  5 23:56:48 [initandlisten] shutdown: going to close sockets...
Sun Jun  5 23:56:48 [initandlisten] shutdown: waiting for fs preallocator...
Sun Jun  5 23:56:48 [initandlisten] shutdown: closing all files...
Sun Jun  5 23:56:48 closeAllFiles() finished
Sun Jun  5 23:56:48 dbexit: really exiting now

[1]で正常終了時には削除されるはずのdata/mongod.lock が残っているとの警告が出されていますね。そして[2]でこのファイルを削除して再起動し、reparコマンドを実行する事を勧めてきています。先ほどは記述しませんでしたが、repairコマンドは、起動後にdb.repairDatabase()を実行する以外に、起動の際に--repair コマンドラインオプションをつけることでも同じことが行えます。また、mongod.lockの削除の際はくれぐれも他のファイルやディレクトリを削除しないように注意して下さい。

$ rm data/mongod.lock 
$ mongod --repair --dbpath data

このように--journalオプションをつけずに復帰した場合は強制終了するまでにディスクに書き込まれていたデータだけが反映されており、実行途中のもの、実行されたもののまだディスクにフラッシュされていないデータはディスクに反映しないまま消失してしまいます。

異常終了時から再起動までの動作を確認する（ジャーナリング機能を有効にしている場合）

それでは次に--journalオプションをつけて起動し、前回使用したnewcollコレクションを一度ドロップしてから同じ処理を行ってみます。

$ mongod --journal --dbpath data

> db.newcoll.drop()
true
> for(var n=0; n<100000; n++){ db.newcoll.insert( { "n": n } ); }
$ ps aux | grep mongod
doryokujin 71504  17.2  0.2  2889368   6684 s015  R+   12:05AM   0:01.34 mongod --journal --dbpath data
$ sudo kill -KILL 71504

それでは--journalオプションをつけたままmongodを再起動してみましょう。そうすると今度は警告も出ずに再起動することができます。サーバーログを見てみましょう：

$ mongod --journal --dbpath data
Mon Jun  6 00:08:24 [initandlisten] MongoDB starting : pid=83165 port=27017 dbpath=data 64-bit 
Mon Jun  6 00:08:24 [initandlisten] db version v1.8.0, pdfile version 4.5
Mon Jun  6 00:08:24 [initandlisten] git version: 9c28b1d608df0ed6ebe791f63682370082da41c0
Mon Jun  6 00:08:24 [initandlisten] build sys info: Darwin erh2.10gen.cc 9.6.0 Darwin Kernel Version 9.6.0: Mon Nov 24 17:37:00 PST 2008; root:xnu-1228.9.59~1/RELEASE_I386 i386 BOOST_LIB_VERSION=1_40
[1]Mon Jun  6 00:08:24 [initandlisten] journal dir=data/journal
[2]Mon Jun  6 00:08:24 [initandlisten] recover begin
[3]Mon Jun  6 00:08:24 [initandlisten] recover lsn: 0
[4]Mon Jun  6 00:08:24 [initandlisten] recover data/journal/j._0
[5]Mon Jun  6 00:08:26 [initandlisten] recover cleaning up
[6]Mon Jun  6 00:08:26 [initandlisten] removeJournalFiles
[7]Mon Jun  6 00:08:26 [initandlisten] recover done
Mon Jun  6 00:08:26 [dur] lsn set 0
Mon Jun  6 00:08:26 [initandlisten] waiting for connections on port 27017
Mon Jun  6 00:08:26 [websvr] web admin interface listening on port 28017

[1]でジャーナルディレクトリの存在を確認し、[2]でrecover（リカバリ）を開始したことを述べています。[3]でlsnファイルから必要なジャーナルファイルを確認し、[4]でジャーナルファイル: j._0 に記述されたオペレーションを実行してリカバリを行っています。これにより、実行されたものの、ディスクに書き込まれていないデータをDBに反映することができます。これにより実際に実行されたオペレーションに対しては、リカバリ時に再実行されることによってデータの変更が保証されることになります。そして[5]で正常にリカバリが行われ、[6]でジャーナルファイルを削除し、[7]でリカバリが終了したことが述べられています。このように、サーバーログを見ればジャーナリング有効時の挙動を理解することが出来ます。

まとめ

さて、いかがでしたでしょうか？途中でも触れましたが、ジャーナリングはまだ導入されたばかりの機能であり、今後はグループコミットのタイミングの短縮化など、より精錬され、デフォルトの機能になることは間違いありませんので、その仕組みがどんなものでどれだけ重要な機能であるかを理解しておくことは非常に重要です。この記事によってその助けになれば幸いです。それではまた。