Atlas 7.0 cluster is not using index

MongoDB Atlas
, ,
1

Hi!

After migrating to MongoDB Atlas (coming from Mongo 3.6 self hosted) one of our queries is suddenly not using the appropriate index anymore. This only happens when the query is executed by our Java application (Mongo Driver version 4.8.1) though. Executing the exact same query via a 3rd party client is working fine.

The query in question is this one (captured from the driver’s debug output, so this should be exactly what is queried by the application:

db.runCommand({
    "find": "transactions",
    "filter": {
        "$and": [
            {
                "gameId": "testgame"
            },
            {
                "refundStatus.refundState": "REFUNDED"
            }
        ]
    },
    "sort": {
        "refundStatus.refundTimestamp": 1
    },
    "limit": 10,
    "$db": "shop-api",
    "$readPreference": {
        "mode": "primaryPreferred"
    }
})

The database contains the following index:

    {
        "v" : 2.0,
        "key" : {
            "gameId" : 1.0,
            "refundStatus.refundState" : 1.0,
            "refundStatus.refundTimestamp" : 1.0
        },
        "name" : "gameId_1_refundStatus.refundState_1_refundStatus.refundTimestamp_1",
        "background" : true,
        "sparse" : true
    }

And this is the slow query log from the Atlas console:

{
  "type": "command",
  "ns": "shop-api.transactions",
  "command": {
    "find": "transactions",
    "filter": {
      "$and": [
        {
          "gameId": "testgame"
        },
        {
          "refundStatus.refundState": "REFUNDED"
        }
      ]
    },
    "sort": {
      "refundStatus.refundTimestamp": 1
    },
    "limit": 100,
    "$db": "shop-api",
    "$clusterTime": {
      "clusterTime": {
        "$timestamp": {
          "t": 1705911957,
          "i": 2
        }
      },
      "signature": {
        "hash": {
          "$binary": {
            "base64": "i9wBKmkJ7mbbRskqg0dSeoW2RJ0=",
            "subType": "00"
          }
        },
        "keyId": 7321982236729803000
      }
    },
    "lsid": {
      "id": {
        "$binary": {
          "base64": "t/6xrxbFS8iRXzu06OaTpA==",
          "subType": "04"
        }
      }
    },
    "apiVersion": "1",
    "apiStrict": true
  },
  "planSummary": "IXSCAN { gameId: 1, createdTimestamp: 1 }",
  "planningTimeMicros": 225,
  "keysExamined": 21303777,
  "docsExamined": 21303777,
  "hasSortStage": true,
  "fromMultiPlanner": true,
  "nBatches": 1,
  "cursorExhausted": true,
  "numYields": 64397,
  "nreturned": 19,
  "queryHash": "874BB3AF",
  "planCacheKey": "B73D2F13",
  "queryFramework": "classic",
  "reslen": 141919,
  "locks": {
    "FeatureCompatibilityVersion": {
      "acquireCount": {
        "r": 64398
      }
    },
    "Global": {
      "acquireCount": {
        "r": 64398
      }
    }
  },
  "readConcern": {
    "level": "local",
    "provenance": "implicitDefault"
  },
  "storage": {
    "data": {
      "bytesRead": 350901972395,
      "timeReadingMicros": 636610182
    },
    "timeWaitingMicros": {
      "cache": 47896
    }
  },
  "cpuNanos": 307048449115,
  "remote": "192.168.43.159:48494",
  "protocol": "op_msg",
  "durationMillis": 882234,
  "v": "7.0.5"
}

As you can see it’s using another, less optimal index instead of the perfectly fitting one. We also tried hinting towards the correct index, but both ways of doing that (via index name or index fields) fail with the planner complaining that it can’t find the index that is hinted:

! com.mongodb.MongoQueryException: Command failed with error 2 (BadValue): 'error processing query: ns=shop-api.transactions limit=100Tree: $and
!     gameId $eq "testgame"
!     refundStatus.refundState $eq "REFUNDED"
! Sort: { refundStatus.refundTimestamp: 1 }
! Proj: {}
!  planner returned error :: caused by :: hint provided does not correspond to an existing index' on server something.mongodb.net:27017. The full response is {"ok": 0.0, "errmsg": "error processing query: ns=shop-api.transactions limit=100Tree: $and\n    gameId $eq \"testgame\"\n    refundStatus.refundState $eq \"REFUNDED\"\nSort: { refundStatus.refundTimestamp: 1 }\nProj: {}\n planner returned error :: caused by :: hint provided does not correspond to an existing index", "code": 2, "codeName": "BadValue", "$clusterTime": {"clusterTime": {"$timestamp": {"t": 1705919042, "i": 1}}, "signature": {"hash": {"$binary": {"base64": "g8awYgROHr4DqOUxic13a6aj3b4=", "subType": "00"}}, "keyId": 7321982236729802757}}, "operationTime": {"$timestamp": {"t": 1705919042, "i": 1}}}

Again, executing the captured query including the hint works just fine from a 3rd party client.

We’re running out of ideas what to do (we also tried dropping and recreating the index) and this is currently impairing our live system. Has anyone experienced something similar or can even provide a hint where to look or what else to try? Any help would be greatly appreciated.

3

Just in case anybody else is encountering this issue, we managed to resolve it by updating the MongoDB Java driver to version 4.11.1 and disabling strictMode for the connection.

2 Likes
4

This topic was automatically closed 5 days after the last reply. New replies are no longer allowed.