Mongodb – Mongo count query taking long time though index is being used

mongodb

The following count query is taking lot more time than expected though index is being used and keysExamined , docsExamined are also less

query = {'indxed_field': 'x',
 'a': 'test',
 'b': {'$ne': True},
 'c': {'$gte': 100},
 'd': 2}

the query time is varying from 10-30 secs for different values mentioned there.Following is the explain output of same query with find (to get explain)

    {u'$clusterTime': {u'clusterTime': Timestamp(1554365186, 14),
      u'signature': {u'hash': Binary('xxxxxxxxxxxxxx', 0),
       u'keyId': 0L}},
     u'executionStats': {u'allPlansExecution': [],
      u'executionStages': {u'advanced': 16917,
       u'alreadyHasObj': 0,
       u'docsExamined': 26218,
       u'executionTimeMillisEstimate': 11263,
       u'filter': {u'$and': [{u'a': {u'$eq': u'test'}},
         {u'b': {u'$eq': 2}},
         {u'c': {u'$gte': 100}},
         {u'$nor': [{u'd': {u'$eq': True}}]}]},
       u'inputStage': {u'advanced': 26218,
        u'direction': u'forward',
        u'dupsDropped': 0,
        u'dupsTested': 0,
        u'executionTimeMillisEstimate': 40,
        u'indexBounds': {u'indxed_field': [u'["x", "y"]']},
        u'indexName': u'indxed_field_1',
        u'indexVersion': 1,
        u'invalidates': 0,
        u'isEOF': 1,
        u'isMultiKey': False,
        u'isPartial': False,
        u'isSparse': False,
        u'isUnique': False,
        u'keyPattern': {u'indxed_field': 1},
        u'keysExamined': 26218,
        u'multiKeyPaths': {u'indxed_field': []},
        u'nReturned': 26218,
        u'needTime': 0,
        u'needYield': 0,
        u'restoreState': 567,
        u'saveState': 567,
        u'seeks': 1,
        u'seenInvalidated': 0,
        u'stage': u'IXSCAN',
        u'works': 26219},
       u'invalidates': 0,
       u'isEOF': 1,
       u'nReturned': 16917,
       u'needTime': 9301,
       u'needYield': 0,
       u'restoreState': 567,
       u'saveState': 567,
       u'stage': u'FETCH',
       u'works': 26219},
      u'executionSuccess': True,
      u'executionTimeMillis': 11271,
      u'nReturned': 16917,
      u'totalDocsExamined': 26218,
      u'totalKeysExamined': 26218},
     u'ok': 1.0,
     u'operationTime': Timestamp(1554365186, 14),
     u'queryPlanner': {u'indexFilterSet': False,
      u'namespace': u'xxxxxxxxxxxx',
      u'parsedQuery': {u'$and': [{u'indxed_field': {u'$eq': u'x'}},
        {u'a': {u'$eq': u'test'}},
        {u'b': {u'$eq': 2}},
        {u'c': {u'$gte': 100}},
        {u'$nor': [{u'd': {u'$eq': True}}]}]},
      u'plannerVersion': 1,
      u'rejectedPlans': [],
      u'winningPlan': {u'filter': {u'$and': [{u'a': {u'$eq': u'test'}},
         {u'b': {u'$eq': 2}},
         {u'c': {u'$gte': 100}},
         {u'$nor': [{u'd': {u'$eq': True}}]}]},
       u'inputStage': {u'direction': u'forward',
        u'indexBounds': {u'indxed_field': [u'["x", "y"]']},
        u'indexName': u'indxed_field_1',
        u'indexVersion': 1,
        u'isMultiKey': False,
        u'isPartial':

 False,
    u'isSparse': False,
    u'isUnique': False,
    u'keyPattern': {u'indxed_field': 1},
    u'multiKeyPaths': {u'indxed_field': []},
    u'stage': u'IXSCAN'},
   u'stage': u'FETCH'}},
 u'serverInfo': {u'gitVersion': u'xxxxxxxxxxxxxxxxxxxxxxxx',
  u'host': u'xxxxxxxxxxxxxxxxxxxxx',
  u'port': 27017,
  u'version': u'x.x.x'}}

And I did a count query in one shell and collected the db.currentOp() output in another shell, that is mentioned below

{
    "inprog" : [
        {
            "host" : "xxxxxxxxxx",
            "desc" : "conn69767",
            "connectionId" : 69767,
            "client" : "127.0.0.1:34876",
            "appName" : "MongoDB Shell",
            "clientMetadata" : {
                "application" : {
                    "name" : "MongoDB Shell"
                },
                "driver" : {
                    "name" : "MongoDB Internal Client",
                    "version" : "4.0.2"
                },
                "os" : {
                    "type" : "Linux",
                    "name" : "Ubuntu",
                    "architecture" : "x86_64",
                    "version" : "16.04"
                }
            },
            "active" : true,
            "currentOpTime" : "2019-04-05T11:56:58.102+0000",
            "opid" : 13776192,
            "lsid" : {
                "id" : UUID("xxxxxxxxxxxx"),
                "uid" : BinData(0,"xxxxxxxxx")
            },
            "secs_running" : NumberLong(5),
            "microsecs_running" : NumberLong(5141567),
            "op" : "command",
            "ns" : "my_collection",
            "command" : {
                "count" : "my_collection",
                "query" : {
                    "indxed_field" : "x",
                    "a" : "test",
                    "b" : {
                        "$ne" : true
                    },
                    "c" : {
                        "$gte" : 190
                    },
                    "d" : 2,
                    "is_deleted" : {
                        "$ne" : true
                    }
                },
                "fields" : {

                },
                "lsid" : {
                    "id" : UUID("xxxxxxxxxxx")
                },
                "$clusterTime" : {
                    "clusterTime" : Timestamp(1554465406, 5),
                    "signature" : {
                        "hash" : BinData(0,"xxxxxxxxx"),
                        "keyId" : NumberLong(0)
                    }
                },
                "$readPreference" : {
                    "mode" : "secondaryPreferred"
                },
                "$db" : "mydb"
            },
            "planSummary" : "IXSCAN { indxed_field: 1 }",
            "numYields" : 260,
            "locks" : {
                "Global" : "r",
                "Database" : "r",
                "Collection" : "r"
            },
            "waitingForLock" : false,
            "lockStats" : {
                "Global" : {
                    "acquireCount" : {
                        "r" : NumberLong(261)
                    }
                },
                "Database" : {
                    "acquireCount" : {
                        "r" : NumberLong(261)
                    }
                },
                "Collection" : {
                    "acquireCount" : {
                        "r" : NumberLong(261)
                    }
                }
            }
        }
    ],
    "ok" : 1,
    "operationTime" : Timestamp(1554465418, 1),
    "$clusterTime" : {
        "clusterTime" : Timestamp(1554465418, 1),
        "signature" : {
            "hash" : BinData(0,"xxxxxxxx"),
            "keyId" : NumberLong(0)
        }
    }
}

I was bit unclear at lockStats section. Any Ideas why the query is taking more time.

Best Answer

Mongo count query taking long time though index is being used

As per MongoDB documentation here To return information on query plans and execution statistics of the query plans, MongoDB provides:

The explain results present the query plans as a tree of stages.

"winningPlan" : {
   "stage" : <STAGE1>,
   ...
   "inputStage" : {
      "stage" : <STAGE2>,
      ...
      "inputStage" : {
         "stage" : <STAGE3>,
         ...
      }
   }
},

Each stage passes its results (i.e. documents or index keys) to the parent node. The leaf nodes access the collection or the indices. The internal nodes manipulate the documents or the index keys that result from the child nodes. The root node is the final stage from which MongoDB derives the result set.

Stages are descriptive of the operation; e.g.

  • COLLSCAN for a collection scan
  • IXSCAN for scanning index keys
  • FETCH for retrieving documents
  • SHARD_MERGE for merging results from shards
  • SHARDING_FILTER for filtering out orphan documents from shards

explain.executionStats.executionStages.inputStage.keysExamined

For query execution stages that scan an index (e.g. IXSCAN), keysExamined is the total number of in-bounds and out-of-bounds keys that are examined in the process of the index scan. If the index scan consists of a single contiguous range of keys, only in-bounds keys need to be examined. If the index bounds consists of several key ranges, the index scan execution process may examine out-of-bounds keys in order to skip from the end of one range to the beginning of the next.

Consider the following example, where there is an index of field x and the collection contains 100 documents with x values 1 through 100:

db.keys.find( { x : { $in : [ 3, 4, 50, 74, 75, 90 ] } } ).explain( "executionStats" )

The query will scan keys 3 and 4. It will then scan the key 5, detect that it is out-of-bounds, and skip to the next key 50.

Continuing this process, the query scans keys 3, 4, 5, 50, 51, 74, 75, 76, 90, and 91. Keys 5, 51, 76, and 91 are out-of-bounds keys that are still examined. The value of keysExamined is 10.

Note: New in version 3.4: For index scan (IXSCAN) stages only. The number of times that we had to seek the index cursor to a new position in order to complete the index scan.

executionStats

The returned executionStats information details the execution of the winning plan. In order to include executionStats in the results, you must run the explain in either:

For unsharded collections, explain returns the following executionStats information:

"executionStats" : {
   "executionSuccess" : <boolean>,
   "nReturned" : <int>,
   "executionTimeMillis" : <int>,
   "totalKeysExamined" : <int>,
   "totalDocsExamined" : <int>,
   "executionStages" : {
      "stage" : <STAGE1>
      "nReturned" : <int>,
      "executionTimeMillisEstimate" : <int>,
      "works" : <int>,
      "advanced" : <int>,
      "needTime" : <int>,
      "needYield" : <int>,
      "saveState" : <int>,
      "restoreState" : <int>,
      "isEOF" : <boolean>,
      ...
      "inputStage" : {
         "stage" : <STAGE2>,
         "nReturned" : <int>,
         "executionTimeMillisEstimate" : <int>,
         ...
         "inputStage" : {
            ...
         }
      }
   },
   "allPlansExecution" : [
      {
         "nReturned" : <int>,
         "executionTimeMillisEstimate" : <int>,
         "totalKeysExamined" : <int>,
         "totalDocsExamined" :<int>,
         "executionStages" : {
            "stage" : <STAGEA>,
            "nReturned" : <int>,
            "executionTimeMillisEstimate" : <int>,
            ...
            "inputStage" : {
               "stage" : <STAGEB>,
               ...
               "inputStage" : {
                 ...
               }
            }
         }
      },
      ...
   ]
}

When an index covers a query, MongoDB can both match the query conditions and return the results using only the index keys; i.e. MongoDB does not need to examine documents from the collection to return the results.

When an index covers a query, the explain result has an IXSCAN stage that is not a descendant of a FETCH stage, and in the executionStats, the totalDocsExamined is 0.

Related Question