[MongoDB] Document-Level-Lock first test drive

Lately MongoDB release rc-0 for 2.8 version which includes document-level-lock through wiredtiger storage engine. We were so curious that we tested it with BillRun - open source billing for enterprise. Most of our deployment use billions of CDRs, so we couldn't wait for production version to check what is the affect on our application stack.

So, first we checked with sample file of about 34,581 documents and here are the results:

2014-11-17 23:45:10 INFO (6): [p13712] Store data of file XXXXXYYY_-_0000057403.20140615_-_1242+0300 with 34581 lines
2014-11-17 23:45:10 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 0 count: 1000
2014-11-17 23:45:11 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 1000 count: 1000
2014-11-17 23:45:11 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 2000 count: 1000
2014-11-17 23:45:11 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 3000 count: 1000
2014-11-17 23:45:11 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 4000 count: 1000
2014-11-17 23:45:11 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 5000 count: 1000
2014-11-17 23:45:12 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 6000 count: 1000
2014-11-17 23:45:12 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 7000 count: 1000
2014-11-17 23:45:12 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 8000 count: 1000
2014-11-17 23:45:12 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 9000 count: 1000
2014-11-17 23:45:12 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 10000 count: 1000
2014-11-17 23:45:13 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 11000 count: 1000
2014-11-17 23:45:13 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 12000 count: 1000
2014-11-17 23:45:13 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 13000 count: 1000
2014-11-17 23:45:13 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 14000 count: 1000
2014-11-17 23:45:13 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 15000 count: 1000
2014-11-17 23:45:14 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 16000 count: 1000
2014-11-17 23:45:14 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 17000 count: 1000
2014-11-17 23:45:14 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 18000 count: 1000
2014-11-17 23:45:14 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 19000 count: 1000
2014-11-17 23:45:14 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 20000 count: 1000
2014-11-17 23:45:14 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 21000 count: 1000
2014-11-17 23:45:14 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 22000 count: 1000
2014-11-17 23:45:15 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 23000 count: 1000
2014-11-17 23:45:15 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 24000 count: 1000
2014-11-17 23:45:15 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 25000 count: 1000
2014-11-17 23:45:15 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 26000 count: 1000
2014-11-17 23:45:15 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 27000 count: 1000
2014-11-17 23:45:15 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 28000 count: 1000
2014-11-17 23:45:16 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 29000 count: 1000
2014-11-17 23:45:16 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 30000 count: 1000
2014-11-17 23:45:16 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 31000 count: 1000
2014-11-17 23:45:16 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 32000 count: 1000
2014-11-17 23:45:16 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 33000 count: 1000
2014-11-17 23:45:16 DEBUG (7): [p13712] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 34000 count: 581

You can see that MongoDB 2.8-rc0 with collection-lock only it took about 6 seconds to process.

Then, we checked how it would process same file with document-lock. So we change Mongo setup to use the new engine WiredTiger with configuration update as follow:

dbpath=/var/lib/mongodb-wired
storageEngine=wiredtiger

And then we process the same file with document-lock:

2014-11-17 23:56:45 INFO (6): [p14422] Store data of file XXXXXYYY_-_0000057403.20140615_-_1242+0300 with 34581 lines
2014-11-17 23:56:45 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 0 count: 1000
2014-11-17 23:56:45 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 1000 count: 1000
2014-11-17 23:56:45 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 2000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 3000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 4000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 5000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 6000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 7000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 8000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 9000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 10000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 11000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 12000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 13000 count: 1000
2014-11-17 23:56:46 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 14000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 15000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 16000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 17000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 18000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 19000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 20000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 21000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 22000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 23000 count: 1000
2014-11-17 23:56:47 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 24000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 25000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 26000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 27000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 28000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 29000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 30000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 31000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 32000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 33000 count: 1000
2014-11-17 23:56:48 DEBUG (7): [p14422] Processor bulk insert to lines XXXXXYYY_-_0000057403.20140615_-_1242+0300 from: 34000 count: 581

Now you can see that with document-lock we cut the process time by half to about 3 seconds, and we're more then proud to announce that BillRun can process 10,000's of lines per second.

Take into account if we're clustering BillRun solution, mean that we are able to map-reduce the process amount by the number of shards.

So now we cannot wait to production version of 2.8, to deploy it for our biggest clients and increase their performance. Meanwhile, we are sure going to join MongoDB bug hunt of 2.8 version.

Thank you and feel free give us feedback in the comments.