Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-54571

queryHash and planCacheKey Fields Absent in getMore Requests

    XMLWordPrintableJSON

Details

    • Fully Compatible
    • v5.0, v4.4, v4.2
    • Query Execution 2021-05-31, Query Execution 2021-06-14, Query Execution 2021-06-28, Query Execution 2021-07-12, Query Execution 2021-07-26, QE 2021-08-09, QE 2021-08-23

    Description

      Hi Team,

      Starting in v4.2, MongoDB introduced the queryHash and planCacheKey that respectively help identify slow queries with the same query shape and the plan cache entry associated with the query.

      Said fields are present in the log from the initial batch for a "slow" query:

      {
        "type": "command",
        "ns": "test.foo",
        "appName": "MongoDB Shell",
        "command": {
          "find": "foo",
          "filter": {
            "a": 1
          },
          "lsid": {
            "id": {
              "$uuid": "564cec84-a387-4fa5-9f50-97eafe97efde"
            }
          },
          "$db": "test"
        },
        "planSummary": "IXSCAN { a: 1 }",
        "cursorid": 8918754329959567000,
        "keysExamined": 101,
        "docsExamined": 101,
        "numYields": 0,
        "nreturned": 101,
        "queryHash": "4B53BE76",
        "planCacheKey": "100FCEBA",
        "reslen": 3825,
        "locks": {
          "ReplicationStateTransition": {
            "acquireCount": {
              "w": 1
            }
          },
          "Global": {
            "acquireCount": {
              "r": 1
            }
          },
          "Database": {
            "acquireCount": {
              "r": 1
            }
          },
          "Collection": {
            "acquireCount": {
              "r": 1
            }
          },
          "Mutex": {
            "acquireCount": {
              "r": 1
            }
          }
        },
        "storage": {
          "data": {
            "bytesRead": 2013,
            "timeReadingMicros": 3
          }
        },
        "protocol": "op_msg",
        "durationMillis": 1
      }
      

      But are absent from any subsequent getMore requests:

      {
        "type": "command",
        "ns": "test.foo",
        "appName": "MongoDB Shell",
        "command": {
          "getMore": 8918754329959567000,
          "collection": "foo",
          "lsid": {
            "id": {
              "$uuid": "564cec84-a387-4fa5-9f50-97eafe97efde"
            }
          },
          "$db": "test"
        },
        "originatingCommand": {
          "find": "foo",
          "filter": {
            "a": 1
          },
          "lsid": {
            "id": {
              "$uuid": "564cec84-a387-4fa5-9f50-97eafe97efde"
            }
          },
          "$db": "test"
        },
        "planSummary": "IXSCAN { a: 1 }",
        "cursorid": 8918754329959567000,
        "keysExamined": 276,
        "docsExamined": 276,
        "cursorExhausted": true,
        "numYields": 0,
        "nreturned": 276,
        "reslen": 10474,
        "locks": {
          "ReplicationStateTransition": {
            "acquireCount": {
              "w": 1
            }
          },
          "Global": {
            "acquireCount": {
              "r": 1
            }
          },
          "Database": {
            "acquireCount": {
              "r": 1
            }
          },
          "Collection": {
            "acquireCount": {
              "r": 1
            }
          },
          "Mutex": {
            "acquireCount": {
              "r": 1
            }
          }
        },
        "storage": {},
        "protocol": "op_msg",
        "durationMillis": 0
      }
      

      This happens for both find and aggregate operations in both v4.2.12 and v4.4.4.

      It would be nice to have these fields present in the getMore requests as not having them makes troubleshooting more difficult and/or inaccurate when using those fields as an analysis criteria, for example:

      1. We might miss the getMore requests.
      2. We might miss a query shape in its entirety if the first batch is slow and the slowness is only observed in subsequent getMore requests.

      Regards
      Diego

      Attachments

        Issue Links

          Activity

            People

              mickey.winters@mongodb.com Mickey Winters
              diego.rodriguez@mongodb.com Diego Rodriguez (Inactive)
              Votes:
              3 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: