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

Looks like optimizer choose improper index or full-scan sometimes.

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Done
    • Affects Version/s: 2.4.14
    • Fix Version/s: None
    • Component/s: MMAPv1, Performance
    • Labels:
      None
    • Operating System:
      ALL
    • Steps To Reproduce:
      Hide

      Don't know.

      Show
      Don't know.

      Description

      Looks like optimizer choose improper index or doing full scan sometimes.
      There's a lot of disk read(page faults) when this case happen (Normal status there's only a few hundreds of disk read, but suddenly disk reads is going up to 10k).
      But I am not sure what execution plan optimizer choose, because looks like there's no way to distinguish execution plan of current running query.

      But execution plan is good when I execute this query manually. But looks like sometimes query running different way. Weird thing is that I can not find documents which is matching "creator_id" even during this pattern of query is running.

      Is there any way to tell the execution plan this query choose?

      • Linux version : 2.6.32-358.6.2.el6.x86_64
      • Total disk data size : 1.3TB (total index size is about 1/3)
      • Total memory : 390GB
      • Indexes

        db01:PRIMARY> db.system.indexes.find().pretty()
        {
            "v" : 1,
            "key" : {
                "_id" : 1
            },
            "ns" : "db1.coll1",
            "name" : "_id_"
        }
        {
            "v" : 1,
            "key" : {
                "creator_id" : 1,
                "fd1" : 1,
                "fd2" : 1,
                "fd3" : 1,
                "fd4" : -1
            },
            "ns" : "db1.coll1",
            "name" : "creator_id_1_fd1_1_fd2_1_fd3_1_fd4_-1"
        }
        {
            "v" : 1,
            "key" : {
                "creator_id" : 1,
                "fd5" : 1,
                "fd6" : 1,
                "_id" : -1
            },
            "ns" : "db1.coll1",
            "name" : "creator_id_1_fd5_1_fd6_1__id_-1"
        }
        {
            "v" : 1,
            "key" : {
                "creator_id" : "hashed"
            },
            "ns" : "db1.coll1",
            "name" : "creator_id_hashed"
        }
        

      • Slow query profiling

        db01:PRIMARY> db.system.profile.find().limit(1).pretty()
        {
            "op" : "getmore",
            "ns" : "db1.coll1",
            "query" : {
                "$comment" : "{\"cmt\": []}",
                "$query" : {
                    "_id" : {
                        "$gt" : ObjectId("51c161965ddbb86926acf403"),
                        "$lt" : ObjectId("ffffffffffffffffffffffff")
                    },
                    "creator_id" : ObjectId("51c1601bb14bd287915f6f76")
                },
                "$orderby" : {
                    "_id" : 1
                }
            },
            "cursorid" : NumberLong("7719472921984034942"),
            "ntoreturn" : 50,
            "keyUpdates" : 0,
            "numYield" : 847485,
            "lockStats" : {
                "timeLockedMicros" : {
                    "r" : NumberLong("41763789634"),
                    "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                    "r" : NumberLong("21953017915"),
                    "w" : NumberLong(7)
                }
            },
            "nreturned" : 6,
            "responseLength" : 152,
            "millis" : 21953838,
            "ts" : ISODate("2015-07-16T00:58:03.175Z"),
            "client" : "127.0.0.10",
            "allUsers" : [ ],
            "user" : ""
        }
        

      • MongoDB Log

      ... getmore db1.coll1 query: { $comment: "{"cmt": []}", $query: { _id: { $gt: ObjectId('51c161965ddbb86926acf403'), $lt: ObjectId('ffffffffffffffffffffffff') }, creator_id: ObjectId('51c1601bb14bd287915f6f76') }, $orderby: { _id: 1 } } cursorid:7327170102889815944 ntoreturn:50 keyUpdates:0 numYields: 899085 locks(micros) r:48861004385 nreturned:12 reslen:284 25602157ms
      ```
      

        Attachments

          Activity

            People

            Assignee:
            sam.kleinman Sam Kleinman (Inactive)
            Reporter:
            matt.lee Matt SeongUck Lee
            Participants:
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: