技術者ブログ
クラウド型WAF「Scutum（スキュータム）」の開発者/エンジニアによるブログです。
金床“Kanatoko”をはじめとする株式会社ビットフォレストの技術チームが、“WAFを支える技術”をテーマに幅広く、不定期に更新中！
ext3上のMongoDBでプチフリを回避する方法
2012年5月30日
はじめに
MongoDBをLinux上で稼働させる場合には、比較的新しいバージョンのカーネルを使用し、ファイルシステムにはext4またはxfsを使用するようにオフィシャルのドキュメント内で説明されています。この理由は、MongoDBではデータベースの中身が増えていくに従い、段階的にやや大きめのファイルがディスク上にあらかじめ確保（プリアロケート）されますが、その際のパフォーマンスにファイルシステムによって大きな差が出るからです。
ext3ではプリアロケートの際、ゼロを連続して書き込むという挙動が発生しますが、ext4やxfsでは実際には書き込みを行わずに済ませてしまうというアプローチを採るようです。そのため、ext3とext4を比較すると大きなパフォーマンスの差が発生します。下記エントリなどが参考になります。
「MongoDBをext3とext4でベンチマークしてみたらext4が圧勝だった。」
MongoDBがファイルをプリアロケートする理由は、ファイルに対してプリアロケートせずに段階的に書き込みを行っていくと、ディスク上において、該当するファイルの実際のデータがあちこちに散らばってしまう（断片化してしまう）からだと思われます。
ext3でのプチフリを再現する
新しいカーネルのext4やxfsが使用できる環境であれば、迷うことなくそれを選択すればよいのですが、場合によっては（使用しているクラウドサービスで比較的古めのCentOSしか使えない場合など）、ext3しか選択肢がないことも考えられます。ext3でプリアロケートが走った場合、どのような挙動となるかについて、テスト用のJavaアプリケーションを書いて確認してみました。
テストは以下のようなコードで行いました。
http://www.jumperz.net/tools/MMongoTest1.java
package test;
import com.mongodb.*;
import java.util.*;
public class MMongoTest1
{
private Random rand = new Random();
private DB db;
private DBCollection coll;
private volatile boolean terminated;
private Object mutex = new Object();
private long _start;
//--------------------------------------------------------------------------------
public static void main( String[] args )
throws Exception
{
( new MMongoTest1() ).execute( args );
}
//--------------------------------------------------------------------------------
public void execute( final String[] args )
throws Exception
{
db = ( new Mongo( args[ 0 ] ) ).getDB( "test" );
coll = db.getCollection( "test" );
_start = System.currentTimeMillis();
( new Thread(){
public void run()
{
for( int i = 0; i < Integer.parseInt( args[ 1 ] ); ++i )
{
insertData();
}
shutdown();
}
} ).start();
( new Thread(){
public void run()
{
while( !terminated )
{
long start = System.currentTimeMillis();
long count = coll.count();
System.out.println( ( new java.util.Date() ) + "\tcount=" + count + "\t" + "time:" + ( System.currentTimeMillis() - start ) + " msec" );
try
{
Thread.sleep( 1000 );
}
catch( Exception e )
{
}
}
synchronized( mutex )
{
mutex.notify();
}
}
} ).start();
synchronized( mutex )
{
mutex.wait();
}
System.out.println( "Done. time:" + ( System.currentTimeMillis() - _start ) );
}
//--------------------------------------------------------------------------------
public void shutdown()
{
terminated = true;
}
//--------------------------------------------------------------------------------
public void insertData()
{
try
{
long start = System.currentTimeMillis();
byte[] buf = new byte[ 1024 ];
rand.nextBytes( buf );
BasicDBObject o = new BasicDBObject();
o.put( "data", new String( buf, "ISO-8859-1" ) );
coll.insert( o, WriteConcern.SAFE );
//coll.insert( o, WriteConcern.NONE );
long took = System.currentTimeMillis() - start;
if( took > 500 )
{
System.out.println( ( new java.util.Date() ) + "\tinsert\ttime:" + ( System.currentTimeMillis() - start ) + " msec" );
}
}
catch( Exception e )
{
e.printStackTrace();
}
}
//--------------------------------------------------------------------------------
}
起動は以下のように行います。
java test.MMongoTest1 127.0.0.1 800000
ひとつめの引数はMongoDBのホスト名、ふたつめはテストとしてinsertを行うドキュメントの数です。この例では127.0.0.1で稼働するMongoDBに対して、ドキュメントを80万回insertすることになります。
アプリケーション内では2つのスレッドがそれぞれ独立して動作します。片方のスレッドはcountクエリを実行し、取得した件数を出力して、1秒間スリープする、という動作を繰り返します。もう一方のスレッドはランダムに生成した意味のない文字列（長さは1024バイト）をひたすらinsertします。こちらのスレッドはスリープはしません。
どちらのスレッドも、それぞれのcountあるいはinsertにかかった時間をミリ秒単位で計測しています。count側のスレッドでは、この時間を毎回必ず出力します。insert側のスレッドでは、insertに500ms以上かかった場合にのみ、出力します。通常、この程度（1024バイト）のサイズのデータであれば、MongoDBでは毎秒数千から数万のドキュメントがinsert可能であり、1つのドキュメントのinsertに500ms以上かかることは考えられません。そのため、このアプリケーションにおいてinsert側のスレッドが時間を出力する際は、何か好ましくないことが起きていると言えるでしょう。
ext3のファイルシステム上において、空のディレクトリを--dbpathに指定し（つまり、クリーンな状態から）、MongoDBを起動して、このアプリケーションを動作させてみます。すると次のような出力となりました。
Mon May 28 13:45:07 JST 2012 count=0 time:25 msec Mon May 28 13:45:08 JST 2012 count=2461 time:1 msec Mon May 28 13:45:09 JST 2012 count=6719 time:0 msec Mon May 28 13:45:10 JST 2012 count=13343 time:1 msec Mon May 28 13:45:11 JST 2012 count=19302 time:0 msec Mon May 28 13:45:12 JST 2012 count=25666 time:0 msec Mon May 28 13:45:13 JST 2012 count=32675 time:1 msec Mon May 28 13:45:14 JST 2012 count=39110 time:0 msec Mon May 28 13:45:15 JST 2012 count=46363 time:0 msec Mon May 28 13:45:16 JST 2012 count=53754 time:0 msec Mon May 28 13:45:17 JST 2012 count=60116 time:1 msec Mon May 28 13:45:18 JST 2012 count=67388 time:0 msec Mon May 28 13:45:19 JST 2012 count=74949 time:0 msec Mon May 28 13:45:20 JST 2012 count=80924 time:1 msec Mon May 28 13:45:21 JST 2012 count=88635 time:0 msec Mon May 28 13:45:22 JST 2012 count=96051 time:0 msec Mon May 28 13:45:23 JST 2012 count=102365 time:1 msec Mon May 28 13:45:24 JST 2012 count=108942 time:0 msec Mon May 28 13:45:25 JST 2012 count=116557 time:1 msec Mon May 28 13:45:26 JST 2012 count=123919 time:0 msec Mon May 28 13:45:27 JST 2012 count=130363 time:0 msec Mon May 28 13:45:28 JST 2012 count=137490 time:1 msec Mon May 28 13:45:29 JST 2012 count=145082 time:0 msec Mon May 28 13:45:30 JST 2012 count=151483 time:1 msec Mon May 28 13:45:31 JST 2012 count=158485 time:0 msec Mon May 28 13:45:32 JST 2012 count=165590 time:0 msec Mon May 28 13:45:33 JST 2012 count=171073 time:1 msec Mon May 28 13:45:34 JST 2012 count=178132 time:0 msec Mon May 28 13:45:35 JST 2012 count=184736 time:4 msec Mon May 28 13:45:36 JST 2012 count=191938 time:0 msec Mon May 28 13:45:37 JST 2012 count=199250 time:1 msec Mon May 28 13:45:38 JST 2012 count=205646 time:0 msec Mon May 28 13:45:39 JST 2012 count=212965 time:0 msec Mon May 28 13:45:40 JST 2012 insert time:556 msec Mon May 28 13:45:40 JST 2012 count=216589 time:0 msec Mon May 28 13:45:41 JST 2012 count=223089 time:0 msec Mon May 28 13:45:42 JST 2012 count=229989 time:1 msec Mon May 28 13:45:43 JST 2012 count=236696 time:0 msec Mon May 28 13:45:44 JST 2012 insert time:720 msec Mon May 28 13:45:44 JST 2012 count=238552 time:1 msec Mon May 28 13:45:45 JST 2012 insert time:1058 msec Mon May 28 13:45:45 JST 2012 count=242127 time:591 msec Mon May 28 13:45:46 JST 2012 count=247452 time:0 msec Mon May 28 13:45:48 JST 2012 count=250239 time:132 msec Mon May 28 13:45:48 JST 2012 insert time:718 msec Mon May 28 13:45:49 JST 2012 count=255530 time:0 msec Mon May 28 13:45:50 JST 2012 count=260536 time:1 msec Mon May 28 13:45:51 JST 2012 insert time:1093 msec Mon May 28 13:45:51 JST 2012 count=264176 time:585 msec Mon May 28 13:45:52 JST 2012 count=269717 time:0 msec Mon May 28 13:45:53 JST 2012 count=276797 time:1 msec Mon May 28 13:45:54 JST 2012 count=283431 time:0 msec Mon May 28 13:45:55 JST 2012 count=289815 time:0 msec Mon May 28 13:45:56 JST 2012 count=295954 time:0 msec Mon May 28 13:45:57 JST 2012 count=299548 time:0 msec Mon May 28 13:45:58 JST 2012 count=305838 time:271 msec Mon May 28 13:46:00 JST 2012 count=309185 time:641 msec Mon May 28 13:46:00 JST 2012 insert time:1155 msec Mon May 28 13:46:02 JST 2012 insert time:1667 msec Mon May 28 13:46:02 JST 2012 count=312283 time:1141 msec Mon May 28 13:46:06 JST 2012 insert time:3653 msec Mon May 28 13:46:06 JST 2012 count=315511 time:3170 msec Mon May 28 13:46:08 JST 2012 count=322900 time:211 msec Mon May 28 13:46:09 JST 2012 count=329233 time:0 msec Mon May 28 13:46:10 JST 2012 count=335292 time:1 msec Mon May 28 13:46:11 JST 2012 count=341821 time:5 msec Mon May 28 13:46:12 JST 2012 count=348184 time:142 msec Mon May 28 13:46:13 JST 2012 count=354373 time:1 msec Mon May 28 13:46:14 JST 2012 count=361387 time:0 msec Mon May 28 13:46:15 JST 2012 count=368111 time:1 msec Mon May 28 13:46:16 JST 2012 count=374537 time:0 msec Mon May 28 13:46:17 JST 2012 count=381615 time:0 msec Mon May 28 13:46:18 JST 2012 count=389052 time:1 msec Mon May 28 13:46:19 JST 2012 count=395150 time:0 msec Mon May 28 13:46:20 JST 2012 count=400741 time:0 msec Mon May 28 13:46:21 JST 2012 count=407833 time:0 msec Mon May 28 13:46:22 JST 2012 count=414800 time:0 msec Mon May 28 13:46:23 JST 2012 count=421669 time:1 msec Mon May 28 13:46:24 JST 2012 count=428922 time:0 msec Mon May 28 13:46:25 JST 2012 count=435894 time:1 msec Mon May 28 13:46:26 JST 2012 count=443246 time:0 msec Mon May 28 13:46:27 JST 2012 insert time:630 msec Mon May 28 13:46:27 JST 2012 count=446725 time:126 msec Mon May 28 13:46:28 JST 2012 count=453475 time:0 msec Mon May 28 13:46:29 JST 2012 count=460125 time:1 msec Mon May 28 13:46:30 JST 2012 count=467330 time:0 msec Mon May 28 13:46:31 JST 2012 count=474643 time:0 msec Mon May 28 13:46:32 JST 2012 count=480637 time:0 msec Mon May 28 13:46:33 JST 2012 count=487520 time:0 msec Mon May 28 13:46:34 JST 2012 count=494862 time:10 msec Mon May 28 13:46:35 JST 2012 count=499692 time:116 msec Mon May 28 13:46:36 JST 2012 count=505505 time:0 msec Mon May 28 13:46:39 JST 2012 insert time:2588 msec Mon May 28 13:46:39 JST 2012 count=511124 time:2393 msec Mon May 28 13:46:41 JST 2012 insert time:1343 msec Mon May 28 13:46:41 JST 2012 count=514482 time:816 msec Mon May 28 13:46:42 JST 2012 count=517716 time:38 msec Mon May 28 13:46:42 JST 2012 insert time:571 msec Mon May 28 13:46:43 JST 2012 insert time:563 msec Mon May 28 13:46:43 JST 2012 count=520797 time:48 msec Mon May 28 13:46:45 JST 2012 count=526010 time:161 msec Mon May 28 13:46:46 JST 2012 insert time:1111 msec Mon May 28 13:46:46 JST 2012 count=531435 time:860 msec Mon May 28 13:46:47 JST 2012 count=536024 time:1 msec Mon May 28 13:46:48 JST 2012 count=540589 time:0 msec Mon May 28 13:46:49 JST 2012 count=546656 time:115 msec Mon May 28 13:46:52 JST 2012 insert time:1742 msec Mon May 28 13:46:52 JST 2012 count=549979 time:1160 msec Mon May 28 13:46:53 JST 2012 insert time:935 msec Mon May 28 13:46:53 JST 2012 count=553185 time:396 msec Mon May 28 13:46:54 JST 2012 count=559634 time:0 msec Mon May 28 13:46:55 JST 2012 count=566457 time:0 msec Mon May 28 13:46:58 JST 2012 insert time:2519 msec Mon May 28 13:46:58 JST 2012 count=568810 time:1801 msec Mon May 28 13:46:58 JST 2012 insert time:508 msec Mon May 28 13:46:59 JST 2012 count=572034 time:0 msec Mon May 28 13:47:01 JST 2012 count=572257 time:1126 msec Mon May 28 13:47:01 JST 2012 insert time:2092 msec Mon May 28 13:47:03 JST 2012 insert time:1093 msec Mon May 28 13:47:03 JST 2012 count=575408 time:578 msec Mon May 28 13:47:04 JST 2012 count=580180 time:1 msec Mon May 28 13:47:05 JST 2012 count=587613 time:125 msec Mon May 28 13:47:06 JST 2012 count=595011 time:1 msec Mon May 28 13:47:07 JST 2012 count=600441 time:0 msec Mon May 28 13:47:08 JST 2012 count=606644 time:1 msec Mon May 28 13:47:09 JST 2012 count=613017 time:108 msec Mon May 28 13:47:10 JST 2012 count=620459 time:0 msec Mon May 28 13:47:11 JST 2012 count=627311 time:0 msec Mon May 28 13:47:12 JST 2012 insert time:656 msec Mon May 28 13:47:12 JST 2012 count=631299 time:360 msec Mon May 28 13:47:13 JST 2012 count=638367 time:0 msec Mon May 28 13:47:14 JST 2012 count=645314 time:0 msec Mon May 28 13:47:15 JST 2012 count=650999 time:8 msec Mon May 28 13:47:16 JST 2012 count=658303 time:0 msec Mon May 28 13:47:17 JST 2012 count=665102 time:0 msec Mon May 28 13:47:18 JST 2012 count=671294 time:1 msec Mon May 28 13:47:19 JST 2012 count=677843 time:0 msec Mon May 28 13:47:20 JST 2012 count=683492 time:0 msec Mon May 28 13:47:21 JST 2012 count=688655 time:1 msec Mon May 28 13:47:22 JST 2012 insert time:553 msec Mon May 28 13:47:22 JST 2012 count=691591 time:0 msec Mon May 28 13:47:23 JST 2012 count=699587 time:32 msec Mon May 28 13:47:24 JST 2012 count=706749 time:0 msec Mon May 28 13:47:25 JST 2012 count=713934 time:0 msec Mon May 28 13:47:26 JST 2012 count=721642 time:12 msec Mon May 28 13:47:27 JST 2012 count=727872 time:0 msec Mon May 28 13:47:28 JST 2012 count=734254 time:0 msec Mon May 28 13:47:29 JST 2012 count=740910 time:1 msec Mon May 28 13:47:30 JST 2012 count=747631 time:0 msec Mon May 28 13:47:31 JST 2012 count=754295 time:1 msec Mon May 28 13:47:32 JST 2012 insert time:761 msec Mon May 28 13:47:32 JST 2012 count=756223 time:0 msec Mon May 28 13:47:33 JST 2012 count=763473 time:0 msec Mon May 28 13:47:34 JST 2012 count=770979 time:0 msec Mon May 28 13:47:35 JST 2012 count=777065 time:1 msec Mon May 28 13:47:36 JST 2012 count=783813 time:0 msec Mon May 28 13:47:37 JST 2012 count=790369 time:1 msec Mon May 28 13:47:38 JST 2012 count=795879 time:0 msec Done. time:152360
残念なことに、insert側のスレッドが何度もログを出力しており、1ドキュメントのinsertに数秒を要するケースが何度かあることがわかります。最も悪い場合（Mon May 28 13:46:06 JST 2012）ではなんと3.6秒もinsertにかかってしまっています。このときcount側のスレッドも結果を得るのに3170ミリ秒（約3.2秒）待たされており、つまりMongoDBがプチフリを起こしてしまっていると言えるでしょう。テスト全体には152秒を要しており、スループットとしては毎秒約5263ドキュメントをinsertしていることになります。
このときMongoDB側では以下のようなログが出力されています。
Mon May 28 13:44:58 [initandlisten] MongoDB starting : pid=7177 port=27017 dbpath=/fast/testdb/ 64-bit host=kaldi
Mon May 28 13:44:58 [initandlisten] db version v2.0.0, pdfile version 4.5
Mon May 28 13:44:58 [initandlisten] git version: 695c67dff0ffc361b8568a13366f027caa406222
Mon May 28 13:44:58 [initandlisten] build info: Linux bs-linux64.10gen.cc 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41
Mon May 28 13:44:58 [initandlisten] options: { dbpath: "/fast/testdb/" }
Mon May 28 13:44:58 [initandlisten] journal dir=/fast/testdb/journal
Mon May 28 13:44:58 [initandlisten] recover : no journal files present, no recovery needed
Mon May 28 13:44:58 [initandlisten] waiting for connections on port 27017
Mon May 28 13:44:58 [websvr] admin web console waiting for connections on port 28017
Mon May 28 13:45:07 [initandlisten] connection accepted from 127.0.0.1:10139 #1
Mon May 28 13:45:07 [initandlisten] connection accepted from 127.0.0.1:10140 #2
Mon May 28 13:45:07 [FileAllocator] allocating new datafile /fast/testdb/test.ns, filling with zeroes...
Mon May 28 13:45:07 [FileAllocator] creating directory /fast/testdb/_tmp
Mon May 28 13:45:07 [FileAllocator] done allocating datafile /fast/testdb/test.ns, size: 16MB, took 0.021 secs
Mon May 28 13:45:07 [FileAllocator] allocating new datafile /fast/testdb/test.0, filling with zeroes...
Mon May 28 13:45:07 [FileAllocator] done allocating datafile /fast/testdb/test.0, size: 64MB, took 0.093 secs
Mon May 28 13:45:07 [FileAllocator] allocating new datafile /fast/testdb/test.1, filling with zeroes...
Mon May 28 13:45:07 [conn1] build index test.test { _id: 1 }
Mon May 28 13:45:07 [conn1] build index done 0 records 0 secs
Mon May 28 13:45:07 [conn1] insert test.test 120ms
Mon May 28 13:45:07 [FileAllocator] done allocating datafile /fast/testdb/test.1, size: 128MB, took 0.189 secs
Mon May 28 13:45:13 [FileAllocator] allocating new datafile /fast/testdb/test.2, filling with zeroes...
Mon May 28 13:45:14 [FileAllocator] done allocating datafile /fast/testdb/test.2, size: 256MB, took 0.418 secs
Mon May 28 13:45:22 [FileAllocator] allocating new datafile /fast/testdb/test.3, filling with zeroes...
Mon May 28 13:45:23 [FileAllocator] done allocating datafile /fast/testdb/test.3, size: 512MB, took 1.1 secs
Mon May 28 13:45:41 [FileAllocator] allocating new datafile /fast/testdb/test.4, filling with zeroes...
Mon May 28 13:45:44 [conn1] insert test.test 719ms
Mon May 28 13:45:44 [FileAllocator] done allocating datafile /fast/testdb/test.4, size: 1024MB, took 2.937 secs
Mon May 28 13:45:45 [conn1] insert test.test 1057ms
Mon May 28 13:45:48 [conn1] insert test.test 717ms
Mon May 28 13:45:48 [conn1] insert test.test 268ms
Mon May 28 13:45:51 [conn1] insert test.test 1092ms
Mon May 28 13:45:52 [conn1] insert test.test 127ms
Mon May 28 13:45:57 [conn1] insert test.test 492ms
Mon May 28 13:45:58 [clientcursormon] mem (MB) res:501 virt:2219 mapped:976
Mon May 28 13:45:58 [conn1] insert test.test 409ms
Mon May 28 13:46:00 [conn1] insert test.test 1154ms
Mon May 28 13:46:02 [conn1] insert test.test 1666ms
Mon May 28 13:46:06 [conn1] insert test.test 3652ms
Mon May 28 13:46:27 [conn1] insert test.test 629ms
Mon May 28 13:46:34 [FileAllocator] allocating new datafile /fast/testdb/test.5, filling with zeroes...
Mon May 28 13:46:36 [conn1] insert test.test 224ms
Mon May 28 13:46:39 [conn1] insert test.test 2587ms
Mon May 28 13:46:41 [conn1] insert test.test 1343ms
Mon May 28 13:46:42 [conn1] insert test.test 569ms
Mon May 28 13:46:43 [conn1] insert test.test 562ms
Mon May 28 13:46:45 [conn1] insert test.test 379ms
Mon May 28 13:46:46 [conn1] insert test.test 1111ms
Mon May 28 13:46:47 [conn1] insert test.test 356ms
Mon May 28 13:46:48 [conn1] insert test.test 279ms
Mon May 28 13:46:49 [conn1] insert test.test 339ms
Mon May 28 13:46:50 [FileAllocator] done allocating datafile /fast/testdb/test.5, size: 2047MB, took 16.115 secs
Mon May 28 13:46:52 [conn1] insert test.test 1741ms
Mon May 28 13:46:53 [conn1] insert test.test 935ms
Mon May 28 13:46:58 [conn1] insert test.test 2518ms
Mon May 28 13:47:01 [conn1] insert test.test 2091ms
Mon May 28 13:47:02 [clientcursormon] mem (MB) res:915 virt:4267 mapped:2000
Mon May 28 13:47:03 [conn1] insert test.test 1092ms
Mon May 28 13:47:03 [conn1] insert test.test 316ms
Mon May 28 13:47:06 [conn1] insert test.test 313ms
Mon May 28 13:47:12 [conn1] insert test.test 655ms
Mon May 28 13:47:32 [conn1] insert test.test 760ms
Mon May 28 13:47:39 [conn1] end connection 127.0.0.1:10139
Mon May 28 13:47:39 [conn2] end connection 127.0.0.1:10140
FileAllocatorがゼロを連続して書き込んでいる様子がログからわかります。ただし、このプリアロケートはクライアントアプリケーション側がフリーズするタイミングと必ずしも重なっているわけではないようです。おそらくOS側が実際にディスクに書き込むタイミング等と関係しているのではないかと思われます。
プチフリを防ぐ
このように、ext3上でMongoDBを動作させる場合、単純なinsertのテストであっても、途中でいきなりプチフリするというイヤな挙動を見せることがわかりました。
今回、このプチフリを回避するために様々な方法を試してみた結果、有効なものが1つ見つかったので、ここで紹介します。
やり方は非常にシンプルで簡単なもので、「本番稼働前に無駄なデータをinsertしてプリアロケートを走らせ、その後データ（コレクション）を削除し、ファイルを再利用させる」というものです。
まず、本番稼働前に、上記のテストアプリケーションのようなものを使って、データを大量にinsertします。データベースファイルが必要な数だけ生成されるのを確認したら、insertを終了します。
次にコンソールなどから、無駄にデータをinsertしたコレクションをごっそり削除します。
db.test.drop();
以上で終了です。コレクションを削除しても、プリアロケート済みのデータベースファイルは削除されず、次回再利用されます。そのため次回はプリアロケートが走らないので、プチフリーズが起こらないという仕組みです。
プチフリが発生しなくなったかどうかテストする
テストを1度行ったコレクション（80万ドキュメントがinsertされたもの）を削除して、もう一度同じテストを走らせてみました。すると出力は次のようになりました。
Mon May 28 13:48:08 JST 2012 count=0 time:28 msec Mon May 28 13:48:09 JST 2012 count=2923 time:1 msec Mon May 28 13:48:10 JST 2012 count=6824 time:1 msec Mon May 28 13:48:11 JST 2012 count=12104 time:0 msec Mon May 28 13:48:12 JST 2012 count=17533 time:0 msec Mon May 28 13:48:13 JST 2012 count=25033 time:0 msec Mon May 28 13:48:14 JST 2012 count=31261 time:0 msec Mon May 28 13:48:15 JST 2012 count=36989 time:1 msec Mon May 28 13:48:16 JST 2012 count=44141 time:0 msec Mon May 28 13:48:17 JST 2012 count=51434 time:0 msec Mon May 28 13:48:18 JST 2012 count=58396 time:118 msec Mon May 28 13:48:19 JST 2012 count=65871 time:0 msec Mon May 28 13:48:20 JST 2012 count=73168 time:0 msec Mon May 28 13:48:21 JST 2012 count=80536 time:1 msec Mon May 28 13:48:22 JST 2012 count=87226 time:0 msec Mon May 28 13:48:23 JST 2012 count=94498 time:1 msec Mon May 28 13:48:24 JST 2012 count=100413 time:0 msec Mon May 28 13:48:25 JST 2012 count=106770 time:0 msec Mon May 28 13:48:26 JST 2012 count=112296 time:1 msec Mon May 28 13:48:27 JST 2012 count=118901 time:0 msec Mon May 28 13:48:28 JST 2012 count=125761 time:4 msec Mon May 28 13:48:29 JST 2012 count=132869 time:0 msec Mon May 28 13:48:30 JST 2012 count=138984 time:0 msec Mon May 28 13:48:31 JST 2012 count=145874 time:1 msec Mon May 28 13:48:32 JST 2012 count=152776 time:0 msec Mon May 28 13:48:33 JST 2012 count=159601 time:1 msec Mon May 28 13:48:34 JST 2012 count=166531 time:0 msec Mon May 28 13:48:35 JST 2012 count=172937 time:0 msec Mon May 28 13:48:36 JST 2012 count=180213 time:0 msec Mon May 28 13:48:37 JST 2012 count=186483 time:69 msec Mon May 28 13:48:38 JST 2012 count=193053 time:1 msec Mon May 28 13:48:39 JST 2012 count=200072 time:0 msec Mon May 28 13:48:40 JST 2012 count=206034 time:0 msec Mon May 28 13:48:41 JST 2012 count=212411 time:0 msec Mon May 28 13:48:42 JST 2012 insert time:673 msec Mon May 28 13:48:42 JST 2012 count=215090 time:0 msec Mon May 28 13:48:43 JST 2012 count=221688 time:1 msec Mon May 28 13:48:44 JST 2012 count=228040 time:0 msec Mon May 28 13:48:45 JST 2012 count=234681 time:0 msec Mon May 28 13:48:46 JST 2012 count=242572 time:0 msec Mon May 28 13:48:47 JST 2012 count=247315 time:0 msec Mon May 28 13:48:48 JST 2012 count=253997 time:1 msec Mon May 28 13:48:49 JST 2012 count=259362 time:0 msec Mon May 28 13:48:50 JST 2012 count=266395 time:0 msec Mon May 28 13:48:51 JST 2012 count=273925 time:0 msec Mon May 28 13:48:52 JST 2012 count=279558 time:0 msec Mon May 28 13:48:53 JST 2012 count=286014 time:1 msec Mon May 28 13:48:54 JST 2012 count=293079 time:2 msec Mon May 28 13:48:55 JST 2012 count=300099 time:19 msec Mon May 28 13:48:56 JST 2012 count=306905 time:154 msec Mon May 28 13:48:57 JST 2012 count=314413 time:0 msec Mon May 28 13:48:58 JST 2012 count=318807 time:0 msec Mon May 28 13:48:59 JST 2012 count=321808 time:146 msec Mon May 28 13:48:59 JST 2012 insert time:728 msec Mon May 28 13:49:00 JST 2012 count=325956 time:230 msec Mon May 28 13:49:01 JST 2012 count=332311 time:0 msec Mon May 28 13:49:02 JST 2012 count=338720 time:17 msec Mon May 28 13:49:03 JST 2012 count=345470 time:0 msec Mon May 28 13:49:04 JST 2012 count=352426 time:1 msec Mon May 28 13:49:05 JST 2012 count=359575 time:0 msec Mon May 28 13:49:06 JST 2012 count=366404 time:7 msec Mon May 28 13:49:07 JST 2012 count=373507 time:3 msec Mon May 28 13:49:08 JST 2012 count=381020 time:0 msec Mon May 28 13:49:09 JST 2012 count=386726 time:0 msec Mon May 28 13:49:10 JST 2012 count=394007 time:0 msec Mon May 28 13:49:11 JST 2012 count=400603 time:1 msec Mon May 28 13:49:12 JST 2012 count=408034 time:0 msec Mon May 28 13:49:13 JST 2012 count=415021 time:1 msec Mon May 28 13:49:14 JST 2012 count=422444 time:0 msec Mon May 28 13:49:15 JST 2012 count=429151 time:1 msec Mon May 28 13:49:16 JST 2012 count=434793 time:7 msec Mon May 28 13:49:17 JST 2012 count=442298 time:0 msec Mon May 28 13:49:18 JST 2012 count=448262 time:0 msec Mon May 28 13:49:19 JST 2012 count=454902 time:0 msec Mon May 28 13:49:20 JST 2012 count=461800 time:1 msec Mon May 28 13:49:21 JST 2012 count=468634 time:0 msec Mon May 28 13:49:22 JST 2012 count=475168 time:1 msec Mon May 28 13:49:23 JST 2012 count=481427 time:1 msec Mon May 28 13:49:24 JST 2012 count=488433 time:0 msec Mon May 28 13:49:25 JST 2012 count=495835 time:1 msec Mon May 28 13:49:26 JST 2012 count=502936 time:0 msec Mon May 28 13:49:27 JST 2012 count=509895 time:0 msec Mon May 28 13:49:28 JST 2012 count=517163 time:0 msec Mon May 28 13:49:29 JST 2012 count=524399 time:1 msec Mon May 28 13:49:30 JST 2012 count=531832 time:0 msec Mon May 28 13:49:31 JST 2012 count=537219 time:1 msec Mon May 28 13:49:32 JST 2012 count=543401 time:0 msec Mon May 28 13:49:33 JST 2012 count=550051 time:0 msec Mon May 28 13:49:35 JST 2012 count=555580 time:196 msec Mon May 28 13:49:36 JST 2012 count=562698 time:0 msec Mon May 28 13:49:37 JST 2012 count=569788 time:2 msec Mon May 28 13:49:38 JST 2012 count=575696 time:0 msec Mon May 28 13:49:39 JST 2012 count=580624 time:0 msec Mon May 28 13:49:40 JST 2012 count=586757 time:1 msec Mon May 28 13:49:41 JST 2012 count=593541 time:0 msec Mon May 28 13:49:42 JST 2012 count=597510 time:135 msec Mon May 28 13:49:42 JST 2012 insert time:576 msec Mon May 28 13:49:43 JST 2012 count=604586 time:0 msec Mon May 28 13:49:44 JST 2012 count=612070 time:0 msec Mon May 28 13:49:45 JST 2012 count=618746 time:0 msec Mon May 28 13:49:46 JST 2012 count=624911 time:0 msec Mon May 28 13:49:47 JST 2012 count=630956 time:1 msec Mon May 28 13:49:48 JST 2012 count=637068 time:0 msec Mon May 28 13:49:49 JST 2012 count=643114 time:0 msec Mon May 28 13:49:50 JST 2012 count=650349 time:0 msec Mon May 28 13:49:51 JST 2012 count=656946 time:0 msec Mon May 28 13:49:52 JST 2012 count=662302 time:1 msec Mon May 28 13:49:53 JST 2012 count=669733 time:0 msec Mon May 28 13:49:54 JST 2012 count=676794 time:1 msec Mon May 28 13:49:55 JST 2012 count=683506 time:0 msec Mon May 28 13:49:56 JST 2012 count=690708 time:1 msec Mon May 28 13:49:57 JST 2012 count=697437 time:0 msec Mon May 28 13:49:58 JST 2012 count=704178 time:0 msec Mon May 28 13:50:00 JST 2012 count=706371 time:717 msec Mon May 28 13:50:00 JST 2012 insert time:1437 msec Mon May 28 13:50:01 JST 2012 insert time:1044 msec Mon May 28 13:50:01 JST 2012 count=710324 time:901 msec Mon May 28 13:50:03 JST 2012 count=713606 time:108 msec Mon May 28 13:50:03 JST 2012 insert time:619 msec Mon May 28 13:50:04 JST 2012 count=720322 time:0 msec Mon May 28 13:50:05 JST 2012 count=727004 time:0 msec Mon May 28 13:50:06 JST 2012 count=733346 time:0 msec Mon May 28 13:50:07 JST 2012 count=740726 time:1 msec Mon May 28 13:50:08 JST 2012 count=747725 time:0 msec Mon May 28 13:50:09 JST 2012 count=754819 time:1 msec Mon May 28 13:50:10 JST 2012 count=761420 time:0 msec Mon May 28 13:50:11 JST 2012 count=768394 time:0 msec Mon May 28 13:50:12 JST 2012 count=775956 time:0 msec Mon May 28 13:50:13 JST 2012 count=783141 time:186 msec Mon May 28 13:50:14 JST 2012 count=789495 time:0 msec Mon May 28 13:50:15 JST 2012 count=795579 time:1 msec Done. time:128100
まだinsertに1.4秒を要する箇所なども見られますが、全体的には非常に良好なペースとなっており、なんと全体に要する時間は前回の150秒に比べ128秒（毎秒6250ドキュメント）と非常に短くなっています。また、このときのMongoDB側のログからも、プリアロケートが走っていないことが確認できます。
Mon May 28 13:48:08 [initandlisten] connection accepted from 127.0.0.1:17905 #4
Mon May 28 13:48:08 [initandlisten] connection accepted from 127.0.0.1:17906 #5
Mon May 28 13:48:08 [conn5] build index test.test { _id: 1 }
Mon May 28 13:48:08 [conn5] build index done 0 records 0.001 secs
Mon May 28 13:48:37 [conn5] insert test.test 298ms
Mon May 28 13:48:42 [conn5] insert test.test 672ms
Mon May 28 13:48:46 [conn5] insert test.test 298ms
Mon May 28 13:48:59 [conn5] insert test.test 727ms
Mon May 28 13:49:00 [conn5] insert test.test 440ms
Mon May 28 13:49:32 [journal] old journal file will be removed: /fast/testdb/journal/j._0
Mon May 28 13:49:42 [conn5] insert test.test 575ms
Mon May 28 13:49:51 [conn5] insert test.test 243ms
Mon May 28 13:50:00 [conn5] insert test.test 1435ms
Mon May 28 13:50:01 [conn5] insert test.test 1043ms
Mon May 28 13:50:03 [conn5] insert test.test 619ms
Mon May 28 13:50:16 [conn5] end connection 127.0.0.1:17906
Mon May 28 13:50:16 [conn4] end connection 127.0.0.1:17905
まとめ
今回はext3上でMongoDBを動作させる場合のプチフリーズについて、再現するテストコードとともに、あらかじめデータベースファイルを生成することでそれを回避する方法について紹介しました。