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

MongoDB 7.0.2 SBE query slow when direct index exists

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • None
    • Query Execution
    • ALL
    • Hide

      Here is an example query which executed in 1.173 seconds (we are seeing up to 10 seconds). Since there is a direct index on customer_user_id: 1, we would expect this to return immediately.

      Note that if you remove deleted_at: null and sort: _id: 1 from the below the result is essentially the same.

      {
  "type": "command",
  "ns": "tablesolution_production.customers",
  "appName": "_________-production-756fdf6d9-kvmmt",
  "command": {
    "find": "customers",
    "$db": "___________production",
    "filter": {
      "deleted_at": null,
      "franchise_id": {
        "$oid": "5b3069a900869bb32e00143f"
      },
      "customer_user_id": {
        "$oid": "6267a29a50102f009b84e9d1"
      }
    },
    "limit": 1,
    "sort": {
      "_id": 1
    },
    "$readPreference": {
      "mode": "secondaryPreferred",
      "maxStalenessSeconds": 90
    },
    "$clusterTime": {
      "clusterTime": {
        "$timestamp": {
          "t": 1698575535,
          "i": 168
        }
      },
      "signature": {
        "hash": {
          "$binary": {
            "base64": "n99TLiSJtTiHLaABvmlpW3MgUh0=",
            "subType": "00"
          }
        },
        "keyId": 7250897925230821000
      }
    },
    "lsid": {
      "id": {
        "$binary": {
          "base64": "ypdlguaMRtaKds622AtuZg==",
          "subType": "04"
        }
      }
    }
  },
  "planSummary": "IXSCAN { customer_user_id: 1 }",
  "planningTimeMicros": 752,
  "keysExamined": 1,
  "docsExamined": 1,
  "hasSortStage": true,
  "fromMultiPlanner": true,
  "nBatches": 1,
  "cursorExhausted": true,
  "numYields": 118,
  "nreturned": 0,
  "queryHash": "4EF91298",
  "planCacheKey": "40FDA966",
  "queryFramework": "sbe",
  "reslen": 248,
  "locks": {
    "FeatureCompatibilityVersion": {
      "acquireCount": {
        "r": 119
      }
    },
    "Global": {
      "acquireCount": {
        "r": 119
      }
    }
  },
  "readConcern": {
    "level": "local",
    "provenance": "implicitDefault"
  },
  "storage": {
    "data": {
      "bytesRead": 474208264,
      "timeReadingMicros": 334080
    }
  },
  "cpuNanos": 1036262981,
  "remote": "10.20.117.178:11491",
  "protocol": "op_msg",
  "durationMillis": 1173,
  "v": "7.0.2"
}

       

      Show
      Here is an example query which executed in 1.173 seconds (we are seeing up to 10 seconds). Since there is a direct index on customer_user_id: 1 , we would expect this to return immediately. Note that if you remove deleted_at: null and sort: _id: 1 from the below the result is essentially the same. { "type" : "command" , "ns" : "tablesolution_production.customers" , "appName" : "_________-production-756fdf6d9-kvmmt" , "command" : { "find" : "customers" , "$db" : "___________production" , "filter" : { "deleted_at" : null , "franchise_id" : { "$oid" : "5b3069a900869bb32e00143f" }, "customer_user_id" : { "$oid" : "6267a29a50102f009b84e9d1" } }, "limit" : 1, "sort" : { "_id" : 1 }, "$readPreference" : { "mode" : "secondaryPreferred" , "maxStalenessSeconds" : 90 }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1698575535, "i" : 168 } }, "signature" : { "hash" : { "$binary" : { "base64" : "n99TLiSJtTiHLaABvmlpW3MgUh0=" , "subType" : "00" } }, "keyId" : 7250897925230821000 } }, "lsid" : { "id" : { "$binary" : { "base64" : "ypdlguaMRtaKds622AtuZg==" , "subType" : "04" } } } }, "planSummary" : "IXSCAN { customer_user_id: 1 }" , "planningTimeMicros" : 752, "keysExamined" : 1, "docsExamined" : 1, "hasSortStage" : true , "fromMultiPlanner" : true , "nBatches" : 1, "cursorExhausted" : true , "numYields" : 118, "nreturned" : 0, "queryHash" : "4EF91298" , "planCacheKey" : "40FDA966" , "queryFramework" : "sbe" , "reslen" : 248, "locks" : { "FeatureCompatibilityVersion" : { "acquireCount" : { "r" : 119 } }, "Global" : { "acquireCount" : { "r" : 119 } } }, "readConcern" : { "level" : "local" , "provenance" : "implicitDefault" }, "storage" : { "data" : { "bytesRead" : 474208264, "timeReadingMicros" : 334080 } }, "cpuNanos" : 1036262981, "remote" : "10.20.117.178:11491" , "protocol" : "op_msg" , "durationMillis" : 1173, "v" : "7.0.2" }  
    • QO 2023-11-13

      (This ticket is one of several issues we at TableCheck had when upgrading from MongoDB 6.0.11 to 7.0.2; refer to https://support.mongodb.com/case/01207868)

      We have a collection Customers with a scalar ID field "customer_user_id" (foreign key). When we query with complex conditions on this field, we see queries taking up to 10 seconds, for example:

       

      "filter": {
  "franchise_id": "5b3069a900869bb32e00143f",
  "customer_user_id": "6267a29a50102f009b84e9d1"
}
(matches 1 document, executionTimeMillis = 6961)

      If we remove the franchise_id condition, the query returns immediately:

       

      "filter": {
  "customer_user_id": "6267a29a50102f009b84e9d1"
}

(matches 2 documents, executionTimeMillis = 0)

      Note that both queries are ultimately selecting the same index (customer_user_id_1).

      Anecdotally we did not see the same issue on the "Classic" query engine. Also, if we hint the affected query with the index it ultimately selects, it executes immediately (executionTimeMillis = 1)

        1. SERVER-82549_explain_fast_query
          7 kB
          Johnny Shields
        2. SERVER-82549_explain_slow_query
          119 kB
          Johnny Shields
        3. SERVER-82549_explain_slow_query_hinted
          8 kB
          Johnny Shields

            Assignee:
            david.storch@mongodb.com David Storch
            Reporter:
            shields@tablecheck.com Johnny Shields
            Votes:
            0 Vote for this issue
            Watchers:
            11 Start watching this issue

              Created:
              Updated:
              Resolved: