Slow running quries

[josh]

Hi,

I notice every now and then, since upgrading to 2.2 I see some slow running quries, some of them are probably due to yields:

Fri Oct 12 10:00:36 [conn5568] query sitemaker.RAT query: { mode: "wide", community_id: "4011010111", app_rev: "28653", component_id: "4567755621" } ntoreturn:1 ntoskip:0 nscanned:231 keyUpdates:0 numYields: 24 locks(micros) r:4436559 nreturned:1 reslen:16659 2978ms

Is there a way to have collection level locking rather than db level?

Others are just a complete mystery:

Fri Oct 12 10:14:47 [conn5089] query sitemaker.RAT query: { mode: "wide", community_id: "4009776438", app_rev: "28653", component_id: "4558485257" } ntoreturn:1 ntoskip:0 nscanned:4 keyUpdates:0 numYields: 1 locks(micros) r:1705851 nreturned:1 reslen:16968 2176ms

2.1 seconds! Would anyone be able to tell me what I would need to look at/log next to get to the bottom of this?

Thanks,

Josh.

[Gianfranco]

Hi Josh,

Are these queries using indexes?

If you run explain() at the end of the find() for example you see if and which index is being used.

Database locking is 2.2

Collecting level locking is planned but without a definitive schedule yet as it impacts a large part of the server code.

https://jira.mongodb.org/browse/SERVER-1240

Gianfranco

[josh]

Hi,

The collections all have indexs and all of the code paths will hit either community or componant_id (both indexd), the slow query above:
db.RAT.find({ mode: "wide", community_id: "4009776438", app_rev: "28653", component_id: "4558485257" }).explain()
{
        "clusteredType" : "ParallelSort",
        "shards" : {
                "data1/mongo1:27021,mongo2:27021" : [
                        {
                                "cursor" : "BtreeCursor component_id_1",
                                "isMultiKey" : false,
                                "n" : 1,
                                "nscannedObjects" : 1,
                                "nscanned" : 1,
                                "nscannedObjectsAllPlans" : 5,
                                "nscannedAllPlans" : 5,
                                "scanAndOrder" : false,
                                "indexOnly" : false,
                                "nYields" : 0,
                                "nChunkSkips" : 0,
                                "millis" : 40,
                                "indexBounds" : {
                                        "component_id" : [
                                                [
                                                        "4558485257",
                                                        "4558485257"
                                                ]
                                        ]
                                },
                                "server" : "mongo1:27021"
                        }
                ]
        },
        "cursor" : "BtreeCursor component_id_1",
        "n" : 1,
        "nChunkSkips" : 0,
        "nYields" : 0,
        "nscanned" : 1,
        "nscannedAllPlans" : 5,
        "nscannedObjects" : 1,
        "nscannedObjectsAllPlans" : 5,
        "millisShardTotal" : 40,
        "millisShardAvg" : 40,
        "numQueries" : 1,
        "numShards" : 1,
        "indexBounds" : {
                "component_id" : [
                        [
                                "4558485257",
                                "4558485257"
                        ]
                ]
        },
        "millis" : 42
}

It goes straight to the right shard and hits the index without any problem. I'm suspecting locks as the problem here, is there anything else I can look at?

Thanks,

Josh.

[Gianfranco]

In the explain output you included, it doesn't show as a slow query with many yields .

Could you try another query hasn't perhaps already run in the system and is the not yet in the active memory set.

Just to get a better sense on a slow query.

Also what is shard setup? sh.status()

And do you have mms installed?

http://mms.10gen.com

It helps to have a better understanding of what all the various pieces of mongo are doing.

Gianfranco

[josh]

This one took over a second but I think it's due to the fact that it wasn't in memory:
db.RAT.find({ component_id: "4560352977" }).explain()

{
        "clusteredType" : "ParallelSort",
        "shards" : {
                "data1/mongo1:27021,mongo2:27021" : [
                        {
                                "cursor" : "BtreeCursor component_id_1",
                                "isMultiKey" : false,

                                "n" : 0,
                                "nscannedObjects" : 0,
                                "nscanned" : 0,
                                "nscannedObjectsAllPlans" : 0,
                                "nscannedAllPlans" : 0,

                                "scanAndOrder" : false,
                                "indexOnly" : false,
                                "nYields" : 0,
                                "nChunkSkips" : 0,

                                "millis" : 0,
                                "indexBounds" : {
                                        "component_id" : [
                                                [
                                                        "4560352977",
                                                        "4560352977"

                                                ]
                                        ]
                                },
                                "server" : "mongo1:27021"
                        }
                ]
        },
        "cursor" : "BtreeCursor component_id_1",

        "n" : 0,
        "nChunkSkips" : 0,
        "nYields" : 0,
        "nscanned" : 0,
        "nscannedAllPlans" : 0,
        "nscannedObjects" : 0,
        "nscannedObjectsAllPlans" : 0,
        "millisShardTotal" : 0,
        "millisShardAvg" : 0,

        "numQueries" : 1,
        "numShards" : 1,
        "indexBounds" : {
                "component_id" : [
                        [

                                "4560352977",
                                "4560352977"
                        ]
                ]
        },
        "millis" : 1397
}


The slow running queries problem is an intermittent one so I can't run .explain() as I never know when it's going to happen, what I can say is that it's usually crippling when it does happend...

I'll install mms on Monday.

Thanks,

Josh.

[josh]

Sorry, forgot to add:
sh.status()
--- Sharding Status ---
  sharding version: { "_id" : 1, "version" : 3 }
  shards:
        {  "_id" : "data1",  "host" : "data1/mongo1:27021,mongo2:27021" }
        {  "_id" : "data2",  "host" : "data2/mongo1:27022,mongo2:27022" }
        {  "_id" : "data3",  "host" : "data3/mongo3:27023,mongo4:27023" }
        {  "_id" : "data4",  "host" : "data4/mongo3:27024,mongo4:27024" }
  databases:
        {  "_id" : "admin",  "partitioned" : false,  "primary" : "config" }
        {  "_id" : "sitemaker",  "partitioned" : true,  "primary" : "data1" }
                sitemaker.CT chunks:
                                data3   370
                                data1   370
                                data4   370
                                data2   377
                        too many chunks to print, use verbose if you want to force print
                sitemaker.CTTHIN chunks:
                                data4   159
                                data2   160
                                data3   159
                                data1   162
                        too many chunks to print, use verbose if you want to force print
                sitemaker.RAT chunks:
                                data3   211
                                data1   211
                                data4   211
                                data2   213
                        too many chunks to print, use verbose if you want to force print
                sitemaker.html chunks:
                                data4   29
                                data2   29
                                data1   32
                                data3   29
                        too many chunks to print, use verbose if you want to force print

[Gianfranco]

See on Monday what mms can help understand better.

1. But in the mean while what's the output of this command on the various shards:

> sudo blockdev --report

To see the Readahead value of the devices where the data is actually stored.

Some more info about this:

http://www.mongodb.org/display/DOCS/Production+Notes#ProductionNotes-Readahead

2. What the resident memory? - how much RAM do they have configured?

> db.serverStatus().mem.mapped

3. What is set up in terms of storage (RAID level, number of drives etc.)? Is it your own hardware/cloud, etc?

[josh]

All the shards have an equal layout:
RO    RA   SSZ   BSZ   StartSec     Size    Device
rw   256   512  1024          0  488281250  /dev/sda
rw   256   512  1024         63     208782  /dev/sda1
rw   256   512   512     208845  486849825  /dev/sda2
rw   256   512  1024          0  488281250  /dev/sdb


Of the 4 shards:
data1:PRIMARY> db.serverStatus().mem.mapped
114793
data2:PRIMARY> db.serverStatus().mem.mapped
149592
data3:PRIMARY> db.serverStatus().mem.mapped
114793
data4:PRIMARY> db.serverStatus().mem.mapped
122981


No raid setup, all the shards are on a single unraded normal disk. The hardware is all our own, they are Dell R210s.

Josh.

[Gianfranco]

Hi Josh,

1) Have you seen any improvements in the queries' performance?

2) Is MMS installed?

Gianfranco