[JAVA-622] Looking for performance tips loading results from a find() with the java driver. Created: 16/Aug/12  Updated: 11/Sep/19  Resolved: 20/Aug/12

Status: Closed
Project: Java Driver
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Task Priority: Major - P3
Reporter: Andrew Lee Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

2.8.0 java driver. Mac OS X (development) & CentOS (production)



 Description   

I had a question about improving the performance of loading data from Mongo.
I'm doing a query as follows:

val prefixString = "^" + Pattern.quote(path);
val prefixPattern: Pattern = Pattern.compile(prefixString);
val query: BasicDBObject = new BasicDBObject(ID_FIELD_NAME, prefixPattern);
val cursor = this.collection.find(query).batchSize(10000);
val arr = cursor.toArray();

I'm using the 2.8.0 java driver (even though the code is written in scala).

When I do an "explain" of this query, I get the following:

{ "cursor" : "BtreeCursor id multi" , "nscanned" : 5020 , "nscannedObjects" : 5020 , "n" : 5020 , "millis" : 23 , "nYields" : 0 , "nChunkSkips" : 0 , "isMultiKey" : false , "indexOnly" : false , "indexBounds" : { "_id" : [ [ "" , { }] , [

{ "$regex" : "^\\Q\\E" , "$options" : ""}

,

{ "$regex" : "^\\Q\\E" , "$options" : ""}

]]} , "allPlans" : [ { "cursor" : "BtreeCursor id multi" , "indexBounds" : { "_id" : [ [ "" , { }] , [

{ "$regex" : "^\\Q\\E" , "$options" : ""}

,

{ "$regex" : "^\\Q\\E" , "$options" : ""}

]]}}] , "oldPlan" : { "cursor" : "BtreeCursor id multi" , "indexBounds" : { "_id" : [ [ "" , { }] , [

{ "$regex" : "^\\Q\\E" , "$options" : ""}

,

{ "$regex" : "^\\Q\\E" , "$options" : ""}

]]}}}

The "explain" says it took 23 milliseconds, but the actual time it takes to do the toArray is closer to 600 ms. This suprises me as I'm doing this testing on localhost, so I would expect the data transfer to go quickly. What can I do to speed this operation up? I want to load all query results into memory as quickly as possible. I took a look in Wireshark and the total data is only 180k, so I'd be surprised if the data transfer were the only issue.

Thanks!



 Comments   
Comment by Andrew Lee [ 20/Aug/12 ]

I submitted a question and it just disappeared. I can't find it anywhere in
the history / haven't gotten any replies. I probably just did something
wrong.


Andrew Lee
Founder, Firebase
http://twitter.com/startupandrew

Comment by Jeffrey Yemin [ 20/Aug/12 ]

What sort of trouble did you have?

Comment by Andrew Lee [ 20/Aug/12 ]

Ok. I originally tried to post to the list but had some trouble so I was told to come here. I'm stopping by the 10gen PA offices today to try to get this all figured out instead. Thanks for your help so far.

Comment by Jeffrey Yemin [ 20/Aug/12 ]

It's pretty clear that this is not an issue with the Java driver, so I'm going to close this. I suggest that you post your question to the mongodb-user Google group, which is a better forum for resolving issues like this.

You'll probably be asked to provide mongostat/iostat numbers during your query runs. That will help engineers to determine the best solution. It may be that you will have to shard your cluster to achieve the scalability that you're looking for, but it's not clear yet.

Comment by Andrew Lee [ 20/Aug/12 ]

One thing I should note is that our _id index is massive (see stats above). I see some stuff online saying that the index needs to fit in memory for performance reasons. Is this likely the source of our problem? If so, is there any way to shrink our index? It's almost as big as our data. We want to use Mongo to store large amounts of data (terabytes), so keeping it all in memory isn't really practical.

Comment by Andrew Lee [ 20/Aug/12 ]

The 14 second number was for the "warm production server" example I sent. Here's a more detailed example of one that takes around 26 seconds:

I'm running this from the command line:

time mongodump --host 10.181.97.165 -d firebase_data -c roll20 -q "

{\"_id\":/^campaign-12688-XkUuoQBmBoRdqIH3TC1mBw/}

" -o datadump2 -u firebase -p "******"
connected to: 10.181.97.165
DATABASE: firebase_data to datadump2/firebase_data
firebase_data.roll20 to datadump2/firebase_data/roll20.bson
200/96142887 0%
41660 objects

real 0m26.772s
user 0m0.004s
sys 0m0.060s

If I delete the output and run the command again I get:

time mongodump --host 10.181.97.165 -d firebase_data -c roll20 -q "

{\"_id\":/^campaign-12688-XkUuoQBmBoRdqIH3TC1mBw/}

" -o datadump2 -u firebase -p "*******"
connected to: 10.181.97.165
DATABASE: firebase_data to datadump2/firebase_data
firebase_data.roll20 to datadump2/firebase_data/roll20.bson
41660 objects

real 0m0.391s
user 0m0.000s
sys 0m0.060s

So it appears that the second time I run the command everything is way faster. This implies to me that the network is not the issue and this is a problem on the mongo side - probably with Mongo loading stuff off disk.

I've emailed the BSON data to you so you can take a look.

What can be done to speed this up? This "prefix" query we're doing is actually the only query we ever do on our data, so I want to do whatever I can to optimize for this use case. We really need the 391ms number and not the 26s number.

Thanks!

Comment by Jeffrey Yemin [ 17/Aug/12 ]

You can do a BSON dump with the bsondump tool: with http://docs.mongodb.org/manual/reference/bsondump/.

The original description in this issue said 600ms. That's the number I was working with. I agree that 14000ms is a different story. Under what circumstances did that occur, and how are they different from the original run that took 600ms? The only difference that you mentioned is that the latter was with a warmed up server.

Comment by Andrew Lee [ 17/Aug/12 ]

What's an easy way to get a BSON dump of the data (command line or otherwise?)? If I can do it from the Java client, then I could simply time the amount of time it takes to dump BSON vrs. time it takes to load all of the data and figure out if that's the issue.

That said I would be very surprised if this is the issue. I can't picture how decoding a few megs of BSON could take 14 seconds.

Comment by Jeffrey Yemin [ 17/Aug/12 ]

I suspect the bottleneck is the speed of UTF-8 string decoding of the BSON, but hard to say for sure without having your data and reproducing locally. Is one CPU pegged during the period of the test?

If possible, please attach a BSON dump of the ~14K documents that match the query, so we can investigate further.

Comment by Andrew Lee [ 16/Aug/12 ]

The documents are all very simple. They simple store a "d" element at the root which contains a number, boolean, or string. They can also contain an optional "p" element as well. There is no nesting of data. We're sort of using Mongo as a key-value store.

Here are some sample documents:

{ "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/campaign/initiativepage/", "d" : false } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/campaign/lastmodified/", "d" : NumberLong(0) } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/campaign/playerpageid/", "d" : "7F73B956-71C3-4C5B-8C72-576EE4F15EA4" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/campaign/snapping_increment/", "d" : NumberLong(1) } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/avatar/", "d" : "http://files.d20.io/images/1433/med.png?1335737429" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/0E7F0D1B-48B9-4B89-B848-76ECC494D3E1/avatar/", "d" : "http://files.d20.io/images/1464/med.png?1335737697" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/0E7F0D1B-48B9-4B89-B848-76ECC494D3E1/id/", "d" : "0E7F0D1B-48B9-4B89-B848-76ECC494D3E1" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/0E7F0D1B-48B9-4B89-B848-76ECC494D3E1/name/", "d" : "Six of Hearts" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/0E7F0D1B-48B9-4B89-B848-76ECC494D3E1/placement/", "d" : NumberLong(99) } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/110C9DF1-360D-40CC-ADAB-1D99F7FC302A/avatar/", "d" : "http://files.d20.io/images/1466/med.png?1335737714" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/110C9DF1-360D-40CC-ADAB-1D99F7FC302A/id/", "d" : "110C9DF1-360D-40CC-ADAB-1D99F7FC302A" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/110C9DF1-360D-40CC-ADAB-1D99F7FC302A/name/", "d" : "Eight of Hearts" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/110C9DF1-360D-40CC-ADAB-1D99F7FC302A/placement/", "d" : NumberLong(99) } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/1252C24A-32B6-499E-A212-355ACAF3C732/avatar/", "d" : "http://files.d20.io/images/1465/med.png?1335737705" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/1252C24A-32B6-499E-A212-355ACAF3C732/id/", "d" : "1252C24A-32B6-499E-A212-355ACAF3C732" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/1252C24A-32B6-499E-A212-355ACAF3C732/name/", "d" : "Seven of Hearts" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/1252C24A-32B6-499E-A212-355ACAF3C732/placement/", "d" : NumberLong(99) } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/13401808-636C-41AA-B7F0-A34D7ED987BF/avatar/", "d" : "http://files.d20.io/images/1472/med.png?1335737762" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/13401808-636C-41AA-B7F0-A34D7ED987BF/id/", "d" : "13401808-636C-41AA-B7F0-A34D7ED987BF" } { "_id" : "campaign-100-Dj7RkJck1aBczmif5NCXjA/decks/A778E120-672D-49D0-BAF8-8646DA3D3FAC/cards/13401808-636C-41AA-B7F0-A34D7ED987BF/name/", "d" : "Ace of Hearts" }

We are basically storing big trees of data in Mongo by storing each node in the tree as a mongo document where the ID is a fully-qualified path to the node. In this way we have very large ID's and indexes but much smaller amounts of data.

Comment by Andrew Lee [ 16/Aug/12 ]

Here are the stats for the database:
db.stats()
{
"db" : "firebase_data",
"collections" : 567,
"objects" : 105508415,
"avgObjSize" : 174.40280224093974,
"dataSize" : 18400963236,
"storageSize" : 31936827328,
"numExtents" : 1268,
"indexes" : 565,
"indexSize" : 24340295392,
"fileSize" : 66473426944,
"nsSizeMB" : 256,
"ok" : 1
}

And for the particular collection I'm querying.

> db.roll20.stats()
{
"ns" : "firebase_data.roll20",
"count" : 92469485,
"size" : 15554540464,
"avgObjSize" : 168.21268620669835,
"storageSize" : 18356551632,
"numExtents" : 39,
"nindexes" : 1,
"lastExtentSize" : 2146426864,
"paddingFactor" : 1,
"flags" : 1,
"totalIndexSize" : 22545344528,
"indexSizes" :

{ "_id_" : 22545344528 }

,
"ok" : 1
}

Comment by Scott Hernandez (Inactive) [ 16/Aug/12 ]

Can you provide an example document, or the data in a bson mongodump file? Do you store large arrays of values in your documents, or deeply nested fields?

Can you provide the stats for your collection?

Comment by Andrew Lee [ 16/Aug/12 ]

Is there a way for me to instrument the query so it tells me the total size of the data transferred over the wire for the query?

Comment by Andrew Lee [ 16/Aug/12 ]

I verified that I can transfer data between machines at ~27 MB / second, so I don't think bandwidth is the issue here.

Comment by Andrew Lee [ 16/Aug/12 ]

This is a "cold" run, you're right. I'm still seeing poor performance for warm boxes as well though. Here's data from a "warm" query on our production servers:
Total Documents Returned: 14303
Total time: 14763ms
Output from Explain:
{ "cursor" : "BtreeCursor id multi" , "nscanned" : 14304 , "nscannedObjects" : 14303 , "n" : 14303 , "millis" : 30 , "nYields" : 0 , "nChunkSkips" : 0 , "isMultiKey" : false , "indexOnly" : false , "indexBounds" : { "_id" : [ [ "campaign-16055-g0d9F0cjEGRPVrVtC9xNCg/" , "campaign-16055-g0d9F0cjEGRPVrVtC9xNCg0"] , [

{ "$regex" : "^\\Qcampaign-16055-g0d9F0cjEGRPVrVtC9xNCg/\\E"}

,

{ "$regex" : "^\\Qcampaign-16055-g0d9F0cjEGRPVrVtC9xNCg/\\E"}

]]} , "allPlans" : [ { "cursor" : "BtreeCursor id multi" , "indexBounds" : { "_id" : [ [ "campaign-16055-g0d9F0cjEGRPVrVtC9xNCg/" , "campaign-16055-g0d9F0cjEGRPVrVtC9xNCg0"] , [

{ "$regex" : "^\\Qcampaign-16055-g0d9F0cjEGRPVrVtC9xNCg/\\E"}

,

{ "$regex" : "^\\Qcampaign-16055-g0d9F0cjEGRPVrVtC9xNCg/\\E"}

]]}}] , "oldPlan" : { "cursor" : "BtreeCursor id multi" , "indexBounds" : { "_id" : [ [ "campaign-16055-g0d9F0cjEGRPVrVtC9xNCg/" , "campaign-16055-g0d9F0cjEGRPVrVtC9xNCg0"] , [

{ "$regex" : "^\\Qcampaign-16055-g0d9F0cjEGRPVrVtC9xNCg/\\E"}

,

{ "$regex" : "^\\Qcampaign-16055-g0d9F0cjEGRPVrVtC9xNCg/\\E"}

]]}}}

I'm estimating the total size of data transferred at between 3-4 megabytes. In production mongo is on a separate physical box, but they're in the same data center and have fast network connections so I would expect 3-4M to be transferred quickly (or is there tuning I need to do to make this happen?).

I would be more likely to chalk this up to a network issue if the write performance were equally slow, but I seem to be able to write data to mongo far faster than I can read it in this way.

Comment by Jeffrey Yemin [ 16/Aug/12 ]

Did you warm up your app with a bunch of queries before starting your timing? It's possible that if this is the first query you're doing, the time includes JIT compilation, opening the socket, etc.

Generated at Thu Feb 08 08:52:42 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.