Different query execution times and keys examined depending on the call method

Hi,
I have a problem with the functioning of the application related to the long response time to the find query.
This is quite strange because if I run the query myself (e.g. via the dataGrip / Intellij driver) the response time is about 500-700 ms, and when it is performed by an application that uses spring data mongo, the response time is from 33000 ms to 45000 ms. Not only the time is different - but verifying the query more specifically using.explain(“executionStats”) - the number of keysExamined.
This is the query:

db.fooCollection.find(
    {"$or": [{"$and": [{"params": {"$elemMatch": {"name": "manufacturer", "val": "FooManufacturer"}}}, {"params": {"$elemMatch": {"name": "articleId", "val": "FOO-FOO-ARTICLE-ID-FOO"}}}]}, {"$and": [{"params": {"$elemMatch": {"name": "brand", "val": "FooManufacturer"}}}, {"params": {"$elemMatch": {"name": "articleId", "val": "FOO-FOO-ARTICLE-ID-FOO"}}}]}]}
    ).collation({locale: 'en', strength: 1, alternate: "shifted", maxVariable: "punct"})
    .explain("executionStats")

This is executionStats from manual query run:

{"executionSuccess": true, "nReturned": new NumberInt("1"), "executionTimeMillis": new NumberInt("2"), "totalKeysExamined": new NumberInt("1"), "totalDocsExamined": new NumberInt("1"), "executionStages": {"stage": "SUBPLAN", "nReturned": new NumberInt("1"), "executionTimeMillisEstimate": new NumberInt("2"), "works": new NumberInt("2"), "advanced": new NumberInt("1"), "needTime": new NumberInt("0"), "needYield": new NumberInt("0"), "saveState": new NumberInt("0"), "restoreState": new NumberInt("0"), "isEOF": new NumberInt("1"), "inputStage": {"stage": "FETCH", "filter": {"$or": [{"$and": [{"params": {"$elemMatch": {"$and": [{"name": {"$eq": "articleId"}}, {"val": {"$eq": "FOO-FOO-ARTICLE-ID-FOO"}}]}}}, {"params": {"$elemMatch": {"$and": [{"name": {"$eq": "brand"}}, {"val": {"$eq":"FooManufacturer"}}]}}}]}, {"$and": [{"params": {"$elemMatch": {"$and": [{"name": {"$eq": "articleId"}}, {"val": {"$eq": "FOO-FOO-ARTICLE-ID-FOO"}}]}}}, {"params": {"$elemMatch": {"$and": [{"name": {"$eq": "manufacturer"}}, {"val": {"$eq": "FooManufacturer"}}]}}}]}]}, "nReturned": new NumberInt("1"), "executionTimeMillisEstimate": new NumberInt("0"), "works": new NumberInt("2"), "advanced": new NumberInt("1"), "needTime": new NumberInt("0"), "needYield": new NumberInt("0"), "saveState": new NumberInt("0"), "restoreState": new NumberInt("0"), "isEOF": new NumberInt("1"), "docsExamined": new NumberInt("1"), "alreadyHasObj": new NumberInt("0"), "inputStage": {"stage": "IXSCAN", "nReturned": new NumberInt("1"), "executionTimeMillisEstimate": new NumberInt("0"), "works": new NumberInt("2"), "advanced": new NumberInt("1"), "needTime": new NumberInt("0"), "needYield": new NumberInt("0"), "saveState": new NumberInt("0"), "restoreState": new NumberInt("0"), "isEOF": new NumberInt("1"), "keyPattern": {"params.name": new NumberInt("1"), "params.val": new NumberInt("1")}, "indexName": "params.name_1_params.val_1", "collation": {"locale": "en", "caseLevel": false, "caseFirst": "off", "strength": new NumberInt("1"), "numericOrdering": false, "alternate": "shifted", "maxVariable": "punct", "normalization": false, "backwards": false, "version": "57.1"}, "isMultiKey": true, "multiKeyPaths": {"params.name": ["params"], "params.val": ["params"]}, "isUnique": false, "isSparse": false, "isPartial": false, "indexVersion": new NumberInt("2"), "direction": "forward", "indexBounds": {"params.name": ["[CollationKey(0xCOLLECTION_KEY), CollationKey(0xCOLLECTION_KEY)]"], "params.val": ["[CollationKey(0xCOLLECTION_KEY_2), CollationKey(0xCOLLECTION_KEY_2)]"]}, "keysExamined": new NumberInt("1"), "seeks": new NumberInt("1"), "dupsTested": new NumberInt("1"), "dupsDropped": new NumberInt("0")}}}}

and this is interesting - from app logs (same query - same db, executed via spring)

 "planSummary": "IXSCAN { params.name: 1, params.val: 1 }, IXSCAN { params.name: 1, params.val: 1 }", "keysExamined": 87182, "docsExamined": 87182, "cursorExhausted": true, "numYields": 484, "nreturned": 1,

I cannot understand how the result of the same query is different in each case. I tried to use an older version of the mongo driver in dataGrip because I thought maybe it was outdated in the application - but it didn’t help. Still hand-made is precise and fast. Both queries (manual and in-app) using same index.

I would be surprised if the same query performed on the same data set on the same server but with different drivers will provide such a big difference in the number of keys examined and execution time.

If the query is the same, the server should take the same logical steps. Something must be different. A subtle difference might make a big difference.

It would be best to share the spring code for the query.

This is spring code:

private suspend fun findByParams(parameters: Set < Map < ParamName, ParamValue >> ): CloseableIterator < ProductDocument > {
    val collation = Collation.of("en").strength(1).alternate("shifted").maxVariable("punct")
    val query = Query().collation(collation)
    val criterias = parameters.map {
        set - > set.map {
            Criteria.where("parameters").elemMatch(Criteria.where("name").iseEqualTo(it.key.name).and("value").isEqualTo(it.value.value))
        }
    }
    query.addCriteria(Criteria().orOperator(criterias.mapNotNull {
        Criteria().andOperator(it)
    }))
    return withContext(Dispatchers.IO) {
        mongoTemplate.stream(query, ProductDocument::class.java)
    }
}

The problem is strange because I manually run the query generated by this method - so I assume that the results should be identical.

You do not seem to query the same fields.

Manually you are doing $elemMatch on the fields name and val while your spring code performs the elemMatch of the fields name and value.

Manual

Spring

Your index being on params.name:1,params.val:1 is fully covers the fields of the manual query but does not covers the field of the spring query because params.value is not part of the index. That is the reason why more keys are examined.

That confirms my suspicions that the query was not the same.

It would appears that it is a simple typing error in your spring code; value rather than val.