[SERVER-32156] Linear field lookup in update subsystem can lead to an individual update having quadratic time complexity Created: 04/Dec/17 Updated: 06/Dec/22 |
|
| Status: | Backlog |
| Project: | Core Server |
| Component/s: | Performance |
| Affects Version/s: | 3.2.16, 3.4.6, 3.6.0 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Craig Leyshan | Assignee: | Backlog - Query Optimization |
| Resolution: | Unresolved | Votes: | 1 |
| Labels: | query-44-grooming | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||
| Assigned Teams: |
Query Optimization
|
||||||||||||||||||||
| Operating System: | ALL | ||||||||||||||||||||
| Steps To Reproduce: | If required, we can provide a mongodump of the collection before it was removed, and some example queries to run against it which seem to hang the server with high CPU and cannot be killed in a timely manner. The dump is about 400MB compressed though. Simply doing: db.Location_Daily.find( {"keys.floorId": "1000000409", "timestamp": 2017120200}); would cause it to hang with high CPU for example. Again there is a unique index on those two attributes. |
||||||||||||||||||||
| Participants: | |||||||||||||||||||||
| Case: | (copied to CRM) | ||||||||||||||||||||
| Description |
|
We had some erroneous data enter our system and get written to a mongo collection. It resulted in a document containing over 600,000 attributes in it. When a find or update was attempted on this document the mongo server master went to 200% CPU and all other work ground to a halt. We attempted to kill the operation but it would not stop. It seemed that the operation was holding locks and was not yielding. Here is a sample of what the currentOp() looked like for the operation:
Note that we have a unique index on the two attributes mentioned in the query so normally these operations take virtually no time. In the end we had to reboot the server several times, delete the bad data, and filter the bad data before it was written. We are not so concerned that a large document could not be updated/read. Rather the real concern is that:
A bit of large (but not humongous) data in one collection should not bring down a whole database. Here's is an idea of what one of the large documents looks like:
Background: It's community edition mongo 3.2.16. We briefly tried on a more recent 3.4.9 locally and the same problem happens on that version too. We are running a 3 data node replica set in production managed by mongo cloud. |
| Comments |
| Comment by Asya Kamsky [ 22/Mar/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Flagging for triage. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Justin Seyster [ 09/Jan/18 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
bruce.lucas Thanks for identifying the quadratic behavior in our update system. With Craig's script, I was able to track down the inefficient code path. The applyChild() in update_object_node.cpp gets called once for each element in the update document, and it performs a linear search of the input document, resulting in O(n * m) behavior for an update document of size n and input document of size m. I wrote a POC below that creates a hash table index that makes the lookup in applyChild constant time (making the whole algorithm O(m + n)). With this optimization in place, an update that previously took 3+ minutes on my test machine now runs in a fraction of a second. It's not exactly a slam dunk, though, because I expect it will be measurably slower for the common case of updates with a very small update document (1-3 elements). We could address this problem by adapting the POC (pasted below) to only create the index when it will be useful (large n and m). We should also investigate if it is necessary for the locks that Bruce identified to be held during the document update.
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 05/Dec/17 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Craig, Thanks for the report and the repro case. I've confirmed that large updates of large documents are O(n^2) and block db operations for the duration. Here's a simple repro:
Some timings:
Here's one stack trace sample from the update, which holds an r lock for an extended time:
There's a thread trying to create a collection which needs a W lock, so it's blocked behind the above query holding the r lock:
All other operations on the db are then stuck behind this. I suspect the underlying cause is that the update runs for a long time without yielding. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Craig Leyshan [ 05/Dec/17 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I have attached 2 scripts. one inserts a single large document. The other performs a very large update to it which takes a very long time (10 minutes roughly). While this update is happening, you cant do much on the database. You can't insert to another collection, or even retrieve list of collection names. currentOp() says that these other actions are waiting on a lock which seems to be held by the long running update. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Craig Leyshan [ 04/Dec/17 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I will upload the diagnostics now. It was a little over 200MB so i've removed some of the older files from the directory to keep it under 150MB. The erroneous data started arriving to our system on the 29th of November, but perf issues came to a head on the 2nd and 3rd of December UTC. The timestamp of the log line for that sample query in the issue description was: 2017-12-03T00:52:01.932+0000 | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 04/Dec/17 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
craig.leyshan@skyfii.com, is it possible to upload the contents of the diagnostic.data directory from the primary node? This directory holds data for about a week, so it should contain stats about what the node was doing during the problematic update. We can also try to generate a large document that has a shape like the one you describe, but if you happen to have copies or a sample dataset with the dirty data you describe we can try to reproduce this behavior here and see if it's cause by a bug in the server. Thanks, | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Craig Leyshan [ 04/Dec/17 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
After a little more investigation, it seems that find is working fine. The issue we had with find is actually the mongo client not being able to render the document, which is not really the issue here. The server can perform the find ok. The actual issue is the updates themselves. The update object was also very large, against a document that was very large. Here's a sample from the mongodb.log:
As can be seen it took over 3 hours to update a single document. While this was going on, the server was at 200% cpu, the replicas were at 100% cpu, and other operations on other collections were unable to complete. |