[SERVER-1745] Query performance very poor when using $all Created: 06/Sep/10  Updated: 16/Apr/12  Resolved: 08/Feb/11

Status: Closed
Project: Core Server
Component/s: Performance
Affects Version/s: 1.6.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Brian C. Dilley Assignee: Aaron Staple
Resolution: Duplicate Votes: 3
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu lucid server with mongodb-stable package from 10gen's apt repository


Attachments: File dump.tar.gz    
Issue Links:
Depends
depends on SERVER-1748 $all matching is slow Closed
Operating System: ALL
Participants:

 Description   

At random (seemingly) the performance of all of our queries using $all (and potentially others) have dropped significantly. Queries that were taking 4 to 20 milliseconds are now taking anywhere from 4 to 10 seconds (sometimes even longer). mongostat only shows a blip on the radar for the queries however (ie: it happens in under a second according to mongostat). Here's an example query:

----- code ---------
db.products.count({ "variations.attributeIds" :

{ "$all" : [ 3873 , 3898]}

, "enabled" : true});
----- / code ---------

another convenient query for timing is:
----- code -----
function timeThis() {
var ret = new Date()+"\n";
ret = db.products.count({ "variations.attributeIds" : { "$all" : [ 3873 , 3898]}})"\n";
ret += new Date();
return ret;
}
timeThis();
----- /code -----

That query takes anywhere from 4 to 8 seconds to execute. CPU usage by the mongod process raises significantly (I'm not sure if this is a bad thing). I've copied the dataset to a machine with 70GB of RAM (yes, 70 gigabytes) and 8 processor cores just to eliminate any potential hardware issues and the problems sill persist.

the following indexes exist:
----- code ---------
db.products.ensureIndex(

{"uid":1}

,

{unique:true, dropDups : true}

);
db.products.ensureIndex(

{weight:-1}

);

db.products.ensureIndex(

{"dateCreated": 1, "weight": -1}

);
db.products.ensureIndex(

{"dateCreated": -1, "weight": -1}

);

db.products.ensureIndex(

{"variations.price": 1, "weight": -1}

);
db.products.ensureIndex(

{"variations.price": -1, "weight": -1}

);

db.products.ensureIndex(

{"variations.salePercent": 1, "weight": -1}

);
db.products.ensureIndex(

{"variations.salePercent": -1, "weight": -1}

);

db.products.ensureIndex(

{"keywords": 1, "weight": -1}

);
db.products.ensureIndex(

{"variations.attributeIds":1}

);
db.products.ensureIndex(

{"variations.attributeIds":1, "enabled":1}

);
----- / code ---------

The dataset attached is half of the collection that is in production that is causing issues, i did the following to reduce it to half:

----- code ---------
function reduceByHalf(colName) {
var i = 0;
var c = 0;
db[colName].find().forEach(function(doc) {
if ((i%2)==0) {
db[colName].remove({_id:doc._id});
c++;
}
i++;
});
return "Deleted "c" documents";
}
reduceByHalf("products");
----- / code ---------

The dataset has roughly 16k documents in it and is attached to this issue in tar/gz format



 Comments   
Comment by Ian Whalen (Inactive) [ 16/Apr/12 ]

@brian that is ticket SERVER-1748

Comment by Brian C. Dilley [ 16/Apr/12 ]

Where is the jira for the slow $all queries?

Comment by Aaron Staple [ 08/Feb/11 ]

Already filed a jira for the slow $all queries

Comment by Aaron Staple [ 07/Sep/10 ]

It looks like mongostat just shows the number of new operations per second, rather than the duration of any particular operation. If you're interested in the time taken by a particular operation, you can use the http interface <http://www.mongodb.org/display/DOCS/Http+Interface> or look at the mongod log.

Comment by Brian C. Dilley [ 07/Sep/10 ]

The other thing that is worth mentioning is that mongostat showed the queries completing in (or under) a second when they obviously did not.

Comment by Aaron Staple [ 07/Sep/10 ]

Thanks for reporting this - you're right, it's slow. I filed SERVER-1748 to represent a fix for the slow component.

Comment by Brian C. Dilley [ 07/Sep/10 ]

So i continued to play with this and found that sometimes variations.attributeIds contained over 3K entries (many times actually) and that's what was slowing things down. Code elsewhere was doing this and causing that to happen. So if you want to close this bug on those grounds that's fine - unless you think it should still perform.

Generated at Thu Feb 08 02:57:54 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.