技術者ブログ

クラウド型WAF「Scutum(スキュータム)」の開発者/エンジニアによるブログです。
金床“Kanatoko”をはじめとする株式会社ビットフォレストの技術チームが、“WAFを支える技術”をテーマに幅広く、不定期に更新中!

2017年10月

1 2 3 4 5 6 7
8 9 10 11 12 13 14
15 16 17 18 19 20 21
22 23 24 25 26 27 28
29 30 31        
  • お問い合わせはこちら
Scutum開発者/エンジニアによる技術ブログ WAF Tech Blog

ext3上のMongoDBでプチフリを回避する方法

はじめに

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を動作させる場合のプチフリーズについて、再現するテストコードとともに、あらかじめデータベースファイルを生成することでそれを回避する方法について紹介しました。