[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), Created: 09/Jan/19  Updated: 10/Jan/19  Resolved: 09/Jan/19

Status: Closed
Project: Core Server
Component/s: Internal Code, Performance
Affects Version/s: 3.6.3
Fix Version/s: None

Type: Question Priority: Major - P3
Reporter: yxyxz123456 Assignee: Danny Hatcher (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by JAVA-3135 slow log questions, why global lock(t... Closed
Participants:

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



 Comments   
Comment by yxyxz123456 [ 10/Jan/19 ]

daniel.hatcher , thanks for you reply, but there is No cause was reported in the log about what happening on the database that slowed the query down.  so I can not find the reasion.

 

Adjacent log:

2019-01-10T09:49:28.544+0800 I ACCESS [conn778798] Successfully authenticated as principal root on admin
2019-01-10T09:49:28.550+0800 I NETWORK [conn778798] end connection 100.90.63.56:42996 (106 connections now open)
2019-01-10T09:49:28.615+0800 I NETWORK [listener] connection accepted from 100.90.63.56:42998 #778799 (107 connections now open)
2019-01-10T09:49:28.615+0800 I NETWORK [conn778799] received client metadata from 100.90.63.56:42998 conn: { application:

{ name: "MongoDB Shell" }

, driver: { name: "MongoDB Internal Client", version: "3.6.3" }, os: { type: "Linux", name: "CentOS Linux release 7.2.1511 (Core) ", architecture: "x86_64", version: "Kernel 3.10.0-514.16.1.el7.x86_64" } }
2019-01-10T09:49:28.633+0800 I ACCESS [conn778799] Successfully authenticated as principal root on admin
2019-01-10T09:49:28.640+0800 I NETWORK [conn778799] end connection 100.90.63.56:42998 (106 connections now open)
2019-01-10T09:49:28.659+0800 I NETWORK [listener] connection accepted from 100.90.63.56:43000 #778800 (107 connections now open)
2019-01-10T09:49:28.672+0800 I ACCESS [conn778800] Successfully authenticated as principal root on admin
2019-01-10T09:49:29.663+0800 I NETWORK [conn778800] end connection 100.90.63.56:43000 (106 connections now open)
2019-01-10T09:49:37.088+0800 I NETWORK [listener] connection accepted from 127.0.0.1:60326 #778801 (107 connections now open)
2019-01-10T09:49:37.088+0800 I NETWORK [conn778801] end connection 127.0.0.1:60326 (106 connections now open)
2019-01-10T09:49:38.525+0800 I NETWORK [listener] connection accepted from 100.90.63.56:43036 #778802 (107 connections now open)
2019-01-10T09:49:38.526+0800 I NETWORK [conn778802] received client metadata from 100.90.63.56:43036 conn: { application:

{ name: "MongoDB Shell" }

, driver: { name: "MongoDB Internal Client", version: "3.6.3" }, os: { type: "Linux", name: "CentOS Linux release 7.2.1511 (Core) ", architecture: "x86_64", version: "Kernel 3.10.0-514.16.1.el7.x86_64" } }
2019-01-10T09:49:38.544+0800 I ACCESS [conn778802] Successfully authenticated as principal root on admin
2019-01-10T09:49:38.549+0800 I NETWORK [conn778802] end connection 100.90.63.56:43036 (106 connections now open)
2019-01-10T09:49:38.615+0800 I NETWORK [listener] connection accepted from 100.90.63.56:43038 #778803 (107 connections now open)
2019-01-10T09:49:38.615+0800 I NETWORK [conn778803] received client metadata from 100.90.63.56:43038 conn: { application:

{ name: "MongoDB Shell" }

, driver: { name: "MongoDB Internal Client", version: "3.6.3" }, os: { type: "Linux", name: "CentOS Linux release 7.2.1511 (Core) ", architecture: "x86_64", version: "Kernel 3.10.0-514.16.1.el7.x86_64" } }
2019-01-10T09:49:38.633+0800 I ACCESS [conn778803] Successfully authenticated as principal root on admin
2019-01-10T09:49:38.641+0800 I NETWORK [conn778803] end connection 100.90.63.56:43038 (106 connections now open)
2019-01-10T09:49:38.659+0800 I NETWORK [listener] connection accepted from 100.90.63.56:43040 #778804 (107 connections now open)
2019-01-10T09:49:38.672+0800 I ACCESS [conn778804] Successfully authenticated as principal root on admin
2019-01-10T09:49:39.663+0800 I NETWORK [conn778804] end connection 100.90.63.56:43040 (106 connections now open)
2019-01-10T09:49:40.300+0800 I COMMAND [conn775371] command liangjian.Driver command: find { find: "Driver", filter:

{ city: 350100, _id: 2832342151806164 }

, shardVersion: [ Timestamp(0, 0), ObjectId('000000000000000000000000') ], $readPreference: { mode: "secondaryPreferred" }, $clusterTime: { clusterTime: Timestamp(1547084980, 156), signature:

{ hash: BinData(0, 867415345C8D172820EA6365202D404615D11C66), 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.81.52:30140", version: "3.6.3" } }, $configServerState: { opTime:

{ ts: Timestamp(1547084977, 178), 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: 282527 } }, Database: { acquireCount:

{ r: 1 }

}, Collection: { acquireCount:

{ r: 1 }

} } protocol:op_msg 282ms
2019-01-10T09:49:40.300+0800 I COMMAND [conn771393] command liangjian.Driver command: find { find: "Driver", filter:

{ city: 340600, _id: 2819749909752575 }

, shardVersion: [ Timestamp(0, 0), ObjectId('000000000000000000000000') ], $readPreference: { mode: "secondaryPreferred" }, $clusterTime: { clusterTime: Timestamp(1547084980, 136), signature:

{ hash: BinData(0, 867415345C8D172820EA6365202D404615D11C66), keyId: 6639872680583495699 }

}, $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-p01.gz01:27024", client: "100.69.111.51:52036", version: "3.6.3" } }, $configServerState: { opTime:

{ ts: Timestamp(1547084977, 178), 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: 283219 } }, Database: { acquireCount:

{ r: 1 }

}, Collection: { acquireCount:

{ r: 1 }

} } protocol:op_msg 283ms

Comment by Danny Hatcher (Inactive) [ 09/Jan/19 ]

Hello,

Thanks for your report.

As a starting point for your investigation, you may wish to look at the metrics we provide at the end of slow queries:

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

Every value is low except for timeAcquiringMicros. This indicates that the issue is not with the query itself but there is something happening on the database that slowed the query down.

Please note that SERVER project is for reporting bugs or feature suggestions for the MongoDB server. For MongoDB-related support discussion please post on the mongodb-user group or Stack Overflow with the mongodb tag. A question like this involving more discussion would be best posted on the mongodb-user group.

Thank you,

Danny

Generated at Thu Feb 08 04:50:23 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.