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

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),

    XMLWordPrintable

    Details

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

      Description

      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"
      }
      ]
      

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                5 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: