> 150ms for returning 70 items in products collection

Ops and Admin
#1

Is >150 ms (sometimes 250) query time expected when querying a 5000 items collection, with 10 - 20 KB item size (product)?
The query is find with $in and a list of product ids.
Items are a bit on the heavy side, but this seems a bit slow.

The server is running Ubuntu and query time is based on mongoDB node driver v3.5.8.

The indexes are being hit, and the VPS isn’t that bad: 4 core / 12 GB RAM / SSD with Xeon E5-2620-V3.

#2

Hi Ivan,

Could you post the output of db.collection.explain('executionStats').find(....) ?

query time is based on mongoDB node driver v3.5.8.

How did you measure the 150-250ms? Did you time it from the app, or did you see it in the server logs? If from the app, does it involve network latency?

Would be helpful if you could also post some example documents, the find() query you did, and the output of db.collection.getIndexes()

Best regards,
Kevin

1 Like
#3

Hi Kevin,

here is the explain output: out.txt

I got the timings by console.time in node js app.

console.time('query_products');
var posts = await postsCol.find(query, productModel).sort(sort)/*.skip((pagination.page-1) * pagination.results ).limit(pagination.results)*/.toArray();				
pagination.total = posts.length;	
console.timeEnd('query_products');

Here are the collection indexes: indexes

Discourse does not allow me to post more than 2 links currently, so I cannot link the document example.
But it is mostly a copy of WordPress post object, with ‘product’ subfield that contains the Woo Commerce product object. The whole document is around 15-20KB long.

#4

Hi Ivan,

Actually the database executed the query pretty quick, in about 3ms, so I think it’s your network roundtrip that’s inflating the query response time:

	"executionStats" : {
		"executionSuccess" : true,
		"nReturned" : 112,
		"executionTimeMillis" : 3,
		"totalKeysExamined" : 453,
		"totalDocsExamined" : 262,

This is also in line with your observation that sometimes it returns in 150ms, other times in 250ms. Typically a database query would be more consistent.

However there are some improvements that can be made on the query side. I believe this is the query:

{ID: {$in: [...]}, post_status: 'publish', post_type: 'product', 'media.featured_image': {$exists: true}

So there’s a couple of things I noticed on the query execution:

  1. From the explain output, it returned 112 documents, examined 453 index keys and 262 documents. That means that it needs to scan ~2x the documents, and ~4x the index keys to return the relevant 112 documents. Ideally, you want the same number on all three of them, meaning the server doesn’t spend any time looking at irrelevant documents/index keys.

  2. I noticed that the query only used the index on the field ID. To back this query properly, you should have a compound index on all the involved fields. Something like db.collection.createIndex({ID:1, post_status:1, post_type:1, 'media.featured_image':1}). See Create Indexes to Support Your Queries for more information.

Regarding point (1) above, it’s a bit hard to achieve with your current query since you have an $exists: true clause. Typically this clause would force MongoDB to load the document from disk to determine if the field is there or not. This can’t really be helped by indexes, since by its nature indexes store what’s in a document, and not what doesn’t exist in a document. To fully solve point (1) then would need a bit of a rethink on how the query and the documents should be structured.

If you’re interested in an in-depth tutorial on data modeling, you might be interested in the free course M320: Data Modeling from MongoDB University.

Best regards,
Kevin

#5

Thanks for the detailed explain, but I still can’t map the 3 to > 100ms slowdown.
Especially since the node app is on the same server as the mongod.
What could cause such a drag in the network layer?
Also, these 3ms are the cursor time, right?

#6

Hi,

What could cause such a drag in the network layer?

Could be many different things, which may not be limited to software. Unfortunately as with most questions regarding performance, there’s no straightforward answers.

You might want to try the same query using the mongo shell and see if it’s faster or slower than the node app.

Also, these 3ms are the cursor time, right?

I believe this is the total time taken by the server for both query planning and execution (see executionTimeMillis). Note that this section also detailed the number of documents examined, which means that the server actually fetched and examined those documents. A cursor-only result wouldn’t fetch documents.

Best regards,
Kevin