Mongo queries are slow and yielding/waiting for locks thousand times
Abhishek Somwanshi
{
"op" : "update",
"ns" : "backend.Scores",
"query" : {
"channel.id" : "hkxj",
"metric" : "YVR",
"date" : ISODate("2018-11-20T10:00:00Z")
},
"updateobj" : {
"$set" : {
"channel" : {
"id" : "hkxj",
"failures" : 39,
"items" : [
{
"_id" : ObjectId("5bf3e434800075956f1"),
"image" : "http://images.abcd.com/something/wscoob.jpg",
"b_time" : ISODate("2018-11-26T19:24:00Z"),
"title" : "What's New ",
"id" : "fq969"
},
{
"_id" : ObjectId("5bf3e43f800075956f0"),
"image" : "http://images.abcd.com/something/w4citv2.jpg",
"broadcast_time" : ISODate("2018-11-26T20:24:00Z"),
"title" : "Let's End This",
"id" : "fsfgd"
}
]
},
"metric" : "YVR",
"date" : ISODate("2018-11-20T10:00:00Z")
},
"$setOnInsert" : {
"__v" : 0
}
},
"nscanned" : 0,
"nscannedObjects" : 2209900,
"nMatched" : 1,
"nModified" : 1,
"keyUpdates" : 0,
"writeConflicts" : 0,
"numYield" : 17264,
"locks" : {
"Global" : {
"acquireCount" : {
"r" : NumberLong(17266),
"w" : NumberLong(17266)
}
},
"Database" : {
"acquireCount" : {
"w" : NumberLong(17266)
}
},
"Collection" : {
"acquireCount" : {
"w" : NumberLong(17265)
}
},
"oplog" : {
"acquireCount" : {
"w" : NumberLong(1)
}
}
},
"millis" : 3864,
"execStats" : {
},
"ts" : ISODate("2018-11-20T10:40:25.104Z"),
"client" : "172.2.3.52",
"allUsers" : [ ],
"user" : ""
}
Robert Cochran
Kevin Adistambha
Hi Abhishek,
I think this part of the output you posted showed what went wrong:
"nscanned" : 0,
"nscannedObjects" : 2209900,
"nMatched" : 1,
"nModified" : 1,
"keyUpdates" : 0,
"writeConflicts" : 0,
"numYield" : 17264,
So the query scanned 2,209,900 documents to find the single one to update. Since nscanned is zero, I think the collection is not indexed, thus MongoDB was forced to load all documents from disk and check if any of them matches the update criteria. As you can imagine, this is very inefficient. The high number of yields was due to MongoDB waiting for the document to be loaded from disk.
In short, the slow performance has nothing to do with locks. It was due to an unindexed update command in a relatively large collection.
I believe this is the query involved in the update:
"query" : {
"channel.id" : "hkxj",
"metric" : "YVR",
"date" : ISODate("2018-11-20T10:00:00Z")
You might want to check if adding an index such as:
db.collection.createIndex({channel.id: 1, metric: 1, date: 1})
would help with this query. See Indexes and Indexing Strategies for more information.
Please try this in a development environment before doing this in production. Also remember to take backups before you do any admin work such as this in your prod environment.
I would also like to reiterate Bob’s comment that MongoDB 3.0 is very old and is out of support. Please consider upgrading to a newer version (4.0.4 is the newest currently) for bugfixes and improvements. For upgrading, please see Upgrade to the Latest Revision of MongoDB, noting that MongoDB would have to be upgraded by following major versions progression, e.g. 3.0 -> 3.2 -> 3.4 -> 3.6 -> 4.0.
Best regards,
Kevin
Abhishek Somwanshi
Kevin Adistambha
Hi Abhishek
According to the What type of locking does MongoDB use, intent lock provides a signal that a thread is intending to do a read or write. This is different from an exclusive lock, which signals the intention to take exclusive access of a resource.
What I understand from the output you posted is that the thread to update yielded 1 time. Typically a thread yields when it’s waiting for something slow to finish, e.g. fetching the needed data from disk. From the output, I see that it’s waiting for an intent lock. Based on this output and the content of the linked page above, I can think of one possibility: the thread is trying to write the update, but it’s forced to wait behind an exclusive lock on that document that was obtained by another thread. Of course, this is probably not the only reason why it’s waiting.
Is this operation generally slow and it’s detrimental to your overall operation? Is this operation always slow, or is it only slow some time? It’s hard to pinpoint what exactly happened when looking at a single occurrence of an event. This could be caused by many things, e.g. slow disk, overburdened server, etc. You might be able to gain a more holistic view of the state of your deployment using tools such as mongostat or mongotop. It’s also best to observe the recommendations in the Production Notes and check if you have any suboptimal setting.
Best regards,
Kevin