#5699 Find source of inefficient mongo query

v1.0.0
closed
Dave Brondsema
performance (126) sf-2 (994)
General
Cory Johns
2015-08-20
2013-01-28
Dave Brondsema
No

Many of these occur in the mongo slow query logs for allura. They come and go.

Mon Jan 28 16:03:03 [conn7317124] query pyforge.project cursorid:3744805240514658737 ntoreturn:1024 ntoskip:772096 nscanned:773121 keyUpdates:0 numYields: 1283 locks(micros) r:2941245 nreturned:1024 reslen:1519021 1552ms

Discussion

  • Dave Brondsema

    Dave Brondsema - 2013-01-28

    Found details via mongo db.currentOp()

        {
        "opid" : 1225439147,
        "active" : true,
        "secs_running" : 0,
        "op" : "query",
        "ns" : "pyforge.project",
        "query" : {

        },
        "client" : "172.29.29.121:48677",
        "desc" : "conn7317124",
        "threadId" : "0x2b62af7bc940",
        "connectionId" : 7317124,
        "locks" : {
            "^" : "r",
            "^pyforge" : "R"
        },
        "waitingForLock" : false,
        "numYields" : 96,
        "lockStats" : {
            "timeLockedMicros" : {
                "r" : NumberLong(1523842),
                "w" : NumberLong(0)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(766111),
                "w" : NumberLong(0)
            }
        }
    },

    That client IP maps to sfs-alluradaemon-1 which has an instance of paster script /var/local/config/production.ini ../scripts/create-allura-sitemap.py running, which I believe is the cause.

     

  • Dave Brondsema

    Dave Brondsema - 2013-01-28

    allura-sitemap.py uses utils.chunked_find which uses skip & limit which requires a lot of scanning to do the skip. Better to use a sort_key and then if it is present chunked_find should use $gt instead of skip. (see sfpy's chunked_find for reference). Can we do this with the _id field for the key?

    Also, we should skip the User neighborhood.

     

  • Dave Brondsema

    Dave Brondsema - 2013-01-28
    • size: --> 2
     

  • Dave Brondsema

    Dave Brondsema - 2013-01-29

    Mongo "proof" of behavior:

    > db.project.find().limit(5).skip(150).explain()
{
    "cursor" : "BasicCursor",
    "nscanned" : 155,
    "nscannedObjects" : 155,
    "n" : 5,
    "millis" : 18,
    "nYields" : 0,
    "nChunkSkips" : 0,
    "isMultiKey" : false,
    "indexOnly" : false,
    "indexBounds" : {

    }
}
> db.project.find({'_id':{$gt:ObjectId("50b633309c104043a8574ec4")}}).limit(5).sort({'_id':1}).explain()
{
    "cursor" : "BtreeCursor _id_",
    "nscanned" : 5,
    "nscannedObjects" : 5,
    "n" : 5,
    "millis" : 17,
    "nYields" : 0,
    "nChunkSkips" : 0,
    "isMultiKey" : false,
    "indexOnly" : false,
    "indexBounds" : {
        "_id" : [
            [
                ObjectId("50b633309c104043a8574ec4"),
                ObjectId("ffffffffffffffffffffffff")
            ]
        ]
    }
}
     

  • Dave Brondsema

    Dave Brondsema - 2013-01-29
    • status: in-progress --> code-review
    • private: Yes --> No
     

  • Dave Brondsema

    Dave Brondsema - 2013-01-29

    Actually I changed my mind and think keeping the Users nbhd in the sitemap is fine. Those pages should get indexed too.

    allura:db/5699

     

  • Tim Van Steenburgh - 2013-01-29
    • qa: Tim Van Steenburgh
     

  • Cory Johns - 2013-01-29
    • qa: Tim Van Steenburgh --> Cory Johns
     

  • Cory Johns - 2013-01-29
    • status: code-review --> validation
     

  • Dave Brondsema

    Dave Brondsema - 2013-01-30

    Today it ran from 10:00 UTC until 16:36. Tomorrow we can compare by looking at ls /nfs/sitemaps/allura_sitemap/ -latr timestamps

     

  • Dave Brondsema

    Dave Brondsema - 2013-01-31

    Sitemap script took about the same amount of time to run, but the slow query is gone from the mongo logs.

    $ egrep -c 'query pyforge.project (cursor|ntoreturn)' mongodb-forge.log.2013-01-{24..31}* mongodb-forge.log
mongodb-forge.log.2013-01-24T00-00-07:734
mongodb-forge.log.2013-01-25T00-00-07:734
mongodb-forge.log.2013-01-26T00-00-02:755
mongodb-forge.log.2013-01-27T00-00-07:743
mongodb-forge.log.2013-01-28T00-00-02:752
mongodb-forge.log.2013-01-29T00-00-08:756
mongodb-forge.log.2013-01-30T00-00-07:758
mongodb-forge.log.2013-01-31T00-00-07:759
mongodb-forge.log:0
     

  • Dave Brondsema

    Dave Brondsema - 2013-01-31
    • status: validation --> closed
     

Log in to post a comment.