[JAVA-3135] 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), Created: 09/Jan/19  Updated: 11/Sep/19  Resolved: 09/Jan/19

Status: Closed
Project: Java Driver
Component/s: Internal, Monitoring, Performance
Affects Version/s: 3.6.3
Fix Version/s: None

Type: Task Priority: Major - P3
Reporter: yxyxz123456 Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: performance
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Linux daijia-newlbs-mongo07.gz01 3.10.0-514.16.1.el7.x86_64 #1 SMP Wed Apr 12 15:04:24 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

32CPU
SSD


Issue Links:
Duplicate
duplicates SERVER-38905 slow log questions, why global lock(t... Closed

 Description   

      why global lock(timeAcquiringMicros) is large, there is no pressure in my mongo service(I/O is low, and have many free memory, and command query is low)

     

    slow log as following:

2019-01-09T18:48:12.300+0800 I COMMAND [conn707992] command liangjian.Driver command: find { find: "Driver", filter: { pos:

{ $near: [ 121.5943918185764, 29.84648735894097 ], $maxDistance: 0.02700683945284377 }

, uptime: { $gte: new Date(1547030592051) }, status: 1, btype: { $bitsAnySet: 7 } }, limit: 10, shardVersion: [ Timestamp(0, 0), ObjectId('000000000000000000000000') ], $readPreference: { mode: "secondaryPreferred" }, $clusterTime: { clusterTime: Timestamp(1547030892, 231), 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-p01.gz01:27024", client: "100.69.94.23:46954", version: "3.6.3" } }, $configServerState: { opTime:

{ ts: Timestamp(1547030887, 374), t: 2 }

}, $db: "liangjian" } planSummary: GEO_NEAR_2D { pos: "2d" } keysExamined:131 docsExamined:146 cursorExhausted:1 numYields:1 nreturned:10 reslen:1525 locks:{ Global: { acquireCount:

{ r: 4 }

, acquireWaitCount: { r: 2 }, timeAcquiringMicros: { r: 243547 } }, Database: { acquireCount:

{ r: 2 }

}, Collection: { acquireCount:

{ r: 2 }

} } protocol:op_msg 247ms

    

 

    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",
"millis" : 335,
"planSummary" : "IXSCAN { _id: 1 }",
"execStats" : {
"stage" : "FETCH",
"filter" : {
"city" :

{ "$eq" : 420100 }

},
"nReturned" : 1,
"executionTimeMillisEstimate" : 0,
"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,
"executionTimeMillisEstimate" : 0,
"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!



 Comments   
Comment by Ramon Fernandez Marina [ 09/Jan/19 ]

Duplicate of SERVER-38905.

Comment by yxyxz123456 [ 09/Jan/19 ]

ross.lawley, thank you for your reply. sorry I choice wrong project.

Comment by Ross Lawley [ 09/Jan/19 ]

Hi wocuocuo,

This ticket has been filed in the JAVA driver project - was that your intent? It doesn't seem to be Java driver related. Do you have production support? If so I will flag this ticket with our support team.

Just to let you know this project is for Java driver bugs or feature requests. The best place for questions regarding MongoDB usage or the Java driver specifics is the mongodb-user mailinglist or stackoverflow as you will reach a broader audience there. If your business requires an answer from MongoDB within a time frame then we do offer production support.

If you do follow up via one of the options above please post a link in this ticket.

Ross

Comment by yxyxz123456 [ 09/Jan/19 ]

sorry, slow log is 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

Comment by yxyxz123456 [ 09/Jan/19 ]

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" :

{ "_id" : 1 }

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

{ "pos" : "2d" }

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

Comment by yxyxz123456 [ 09/Jan/19 ]

I really can't figure out the cause of the problem,I spent a lot of time on this,but can not find the reasion.

It is only 100 queries per second.

Comment by yxyxz123456 [ 09/Jan/19 ]

 There is also very little data。

lbs2_1:SECONDARY> db.Driver.count()
32192
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") }
Generated at Thu Feb 08 08:58:52 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.