slow log questions, why global lock(timeAcquiringMicros) is large, there is no pressure in my mongo service(I/O is low, and have many free memory， There is also very little data，all query use the index),

XMLWordPrintableJSON

    • Type: Question
    • Resolution: Done
    • Priority: Major - P3
    • None
    • Affects Version/s: 3.6.3
    • Component/s: Internal Code, Performance
    • None
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      slow log as following:

      2019-01-09T18:48:12.295+0800 I COMMAND [conn708486] command liangjian.Driver command: find { find: "Driver", filter: { city: 330100, _id: 2832342244067284 }, shardVersion: [ Timestamp(0, 0), ObjectId('000000000000000000000000') ], $readPreference: \{ mode: "secondaryPreferred" }, $clusterTime: { clusterTime: Timestamp(1547030892, 230), signature: { hash: BinData(0, 35C6E6D602FDFE11307659B12361C9C11B6AB206), keyId: 6639872680583495699 }}, $client: { driver:{ name: "mongo-java-driver", version: "3.4.0" }, os: \{ type: "Linux", name: "Linux", architecture: "amd64", version: "2.6.32-642.6.2.el6.toav3.x86_64" }, platform: "Java/Oracle Corporation/1.7.0_79-mockbuild_2015_07_24_09_26-b00", mongos: \{ host: "fd-mongos-p02.gz01:27024", client: "100.69.81.52:53728", version: "3.6.3" } }, $configServerState: { opTime:{ ts: Timestamp(1547030887, 374), t: 2 }}, $db: "liangjian" } planSummary: IXSCAN \{ _id: 1 } keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:454 locks:{ Global: { acquireCount:{ r: 2 } , acquireWaitCount: \{ r: 1 }, timeAcquiringMicros: \{ r: 270459 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_msg 335ms

      system.profile as following:

      lbs2_1:SECONDARY> db.system.profile.findOne()
{
"op" : "query",
"ns" : "liangjian.Driver",
"command" : {
"find" : "Driver",
"filter" : { "city" : 420100, "_id" : NumberLong("2817439193438706") },
"shardVersion" : [ Timestamp(0, 0), ObjectId("000000000000000000000000") ],
"$readPreference" : { "mode" : "secondaryPreferred" },
"$clusterTime" : { "clusterTime" : Timestamp(1547033350, 368),
"signature" : { "hash" : BinData(0,"3M+JVUPxF98AftZMDEvZHL1OUnw="), "keyId" : NumberLong("6639871413568143379") } },
"$client" : { "driver" : { "name" : "mongo-java-driver", "version" : "3.4.0" } , "os" : { "type" : "Linux", "name" : "Linux", "architecture" : "amd64", "version" : "2.6.32-573.18.1.el6.toa.x86_64" } , "platform" : "Java/Oracle Corporation/1.7.0_75-b13",
"mongos" : { "host" : "fd-mongos-p02.gz01:27023", "client" : "100.69.96.50:37941", "version" : "3.6.3" } },
"$configServerState" : { "opTime" : { "ts" : Timestamp(1547033345, 579), "t" : NumberLong(2) } },
"$db" : "liangjian" },
"keysExamined" : 1,
"docsExamined" : 1,
"cursorExhausted" : true,
"numYield" : 0,
"locks" : {
"Global" : {
"acquireCount" : { "r" : NumberLong(2) } , "acquireWaitCount" : { "r" : NumberLong(1) } , "timeAcquiringMicros" : { "r" : NumberLong(324445) } },
"Database" : {
"acquireCount" : { "r" : NumberLong(1) } }, "Collection" : { "acquireCount" : { "r" : NumberLong(1) } } },
"nreturned" : 1,
"responseLength" : 454,
"protocol" : "op_msg",
"{color:#ff0000}*millis" : 335,*{color}
"planSummary" : "IXSCAN \{ _id: 1 }",
"execStats" : {
"stage" : "FETCH",
"filter" : {
"city" : { "$eq" : 420100 } },
"nReturned" : 1,
{color:#ff0000}_*"executionTimeMillisEstimate" : 0,*_{color}
"works" : 2,
"advanced" : 1,
"needTime" : 0,
"needYield" : 0,
"saveState" : 0,
"restoreState" : 0,
"isEOF" : 1,
"invalidates" : 0,
"docsExamined" : 1,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 1,
{color:#FF0000}*"executionTimeMillisEstimate" : 0,*{color}
"works" : 2,
"advanced" : 1,
"needTime" : 0,
"needYield" : 0,
"saveState" : 0,
"restoreState" : 0,
"isEOF" : 1,
"invalidates" : 0,
"keyPattern" : { "_id" : 1 } ,
"indexName" : "_id_",
"isMultiKey" : false,
"multiKeyPaths" : { "_id" : [ ] } ,
"isUnique" : true,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : { "_id" : [ "[2817439193438706, 2817439193438706]" ] } ,
"keysExamined" : 1,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0 } },
"ts" : ISODate("2019-01-09T11:29:10.368Z"),
"client" : "100.69.186.20",
"allUsers" : [ { "user" : "__system", "db" : "local" } ],
"user" : "__system@local"

      The problem doesn't come up very often, it comes up once in a while，who can help me, thanks!

      There is also very little data。

      {color:#FF0000}*lbs2_1:SECONDARY> db.Driver.count()*{color}
{color:#FF0000}*32192*{color}
lbs2_1:SECONDARY>

lbs2_1:SECONDARY> db.Driver.findOne()

{ "_id" : NumberLong("2832342339258825"), "bearing" : 177.83, "btype" : 1, "city" : 440300, "pos" : [ 113.83745279947917, 22.79087836371528 ], "status" : 4, "uptime" : ISODate("2019-01-09T12:14:00.130Z") }

{color:#FF0000}It is only 100 queries per second.{color}

      all the request use the index, It shouldn't be so slow，There is also very little data

      lbs2_1:SECONDARY> db.Driver.getIndexes()
[
{
"v" : 2,
"key" :

{color:#FF0000}{ "_id" : 1 }{color}

,
"name" : "_id_",
"ns" : "liangjian.Driver"
},
{
"v" : 2,
"key" :

{color:#FF0000}{ "pos" : "2d" }{color}

,
"name" : "pos_2d",
"ns" : "liangjian.Driver"
}
]

            Assignee:
            Danny Hatcher (Inactive)
            Reporter:
            yxyxz123456
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: