[SERVER-44752] Big CPU performance regression between 4.0.13 and 4.2.1 (on deletion it seems), about 16 times Created: 20/Nov/19 Updated: 08/Feb/20 Resolved: 08/Feb/20 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | WiredTiger |
| Affects Version/s: | 4.2.1 |
| Fix Version/s: | 4.2.3 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Adrien Jarthon | Assignee: | Bruce Lucas (Inactive) |
| Resolution: | Duplicate | Votes: | 1 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||
| Issue Links: |
|
||||||||||||
| Operating System: | ALL | ||||||||||||
| Participants: | |||||||||||||
| Case: | (copied to CRM) | ||||||||||||
| Description |
|
Hi, it's me again with another big performance regression
Mind the scale here, the average CPU usage went from ~12% to ~15% (not a big deal as I noticed a decreased in disk IO write so I don't consider this a regression) But the spike in the middle during this cron, went from from +10% to +40% and the duration went from 30 minutes to ~2h, which means 16 times more CPU time generated by this script ! By looking at the log of the mongo requests this cron makes looking for the reason of the time increase I noticed there were no more calls than usual but the deletes were taking much longer, about 2s with 4.2.1 instead of 0.1s with 4.0.13, also they are getting slower and slower it seems. The script is doing roughly 300k inserts one after the other, interleaved with 5k deletes, all in the same collection. These are big delete though, containing up to 1000 IDs each.
I'll upload the full log for the Oct 17th and Oct 19th samples and the diagnostic data as soon as you provide an upload portal. |
| Comments |
| Comment by Bruce Lucas (Inactive) [ 08/Feb/20 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks, good idea. And thanks again for reporting this, and for your patience while we diagnosed and fixed it. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Adrien Jarthon [ 08/Feb/20 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
You may want to enter "4.2.3" as Fix Version for people who find this ticket later? | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 08/Feb/20 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks for the update Adrien. I will go ahead and close this ticket then. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Adrien Jarthon [ 08/Feb/20 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi again, I put 4.2.3 in production 5 days ago and I'm please to say that the CPU usage during my daily load is down again, back to similar levels than 4.0.13, if not slightly lower. Thanks! | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 24/Dec/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks Adrien. Will leave this ticket open in "waiting for user" state until then. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Adrien Jarthon [ 23/Dec/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Great, I will not have much time to do testing in the coming weeks so I'm gonna wait for | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 23/Dec/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks for the testing bigbourin@gmail.com. It's good to hear that 4.2.2 was a substantial improvement. Regarding the remaining regression, I think there's a good chance this is
If you're willing to continue pursuing this on your end we can leave this ticket open; please let me know which course you would prefer. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Adrien Jarthon [ 21/Dec/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Ok so I tested 4.2.2 again as primary, and the good news is that it's much better, the bad news is that's it's still more than twice as CPU consuming as 4.0.13, here is a nice chart I made comparing 4.0.13 and 4.2.2 under this same daily load: I show the same time period from 2 different days:
About the CPU increase under normal load, this machine with 4.2.2 has slightly more load and I already noticed (in the description) a small CPU regression in general which IMO is not a big deal because 4.2 brings lower I/O usage in return. So here we're looking at the big load in the middle mostly. Here is a recap table of how long the cron takes and how much CPU time mongo consumes:
I uploaded the diagnostic data file covering Dec 16th and Dec 19th where you can find this load (starts at 11:05am UTC or 10:05am UTC depending on the server because they are not on the same timezone) All in all this is much more acceptable of course, but still making mongo fast is hard so avoiding regression as soon as possible when it's easier to remove should be important to you guys I guess? so we avoid this kind of things: But if you judge this normal and don't want to fix I won't be mad if you close. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Adrien Jarthon [ 06/Dec/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks Bruce, I'll give 4.2.2 a try when it's available in the repos then and will let you know how it goes. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 06/Dec/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
bigbourin@gmail.com, thanks very much for the further details. Meanwhile we have identified a couple of performance issues in 4.2 that are potential candidates.
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Adrien Jarthon [ 22/Nov/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Sure I can! Yes the script runs from 11:05 to 11:35 (under 4.0) and 11:05 to 12:56 (under 4.2). What it does basically is aggregate together some time series data, for example it'll take 24 hourly records and merge them in a 1 daily record, thus producing 24 deleted and 1 insert. Here is code of the Mongoid model and the compact method which is called every day at 11am to group hourly entries from 2 days back into daily records:
There is some finds in between as you said, to find if the daily record exists before creating it (in which case it is updated) and also some getMore to iterate on the apdex records to aggregate. I have batched the delete in group of 1000 because it used to be much faster than doing one by one or smaller batches at least in 3.4, 3.6 and 4.0. There is indeed a constant (and very stable) stream of queries on the server. It's running my monitoring service https://updown.io and each monitoring request I do will update the apdex collection (using the `report` method visible above), this method does a find query and then either an update or an insert (most often update), it is called about 160 times/second. There is also some update on other collections at the same time. There is also as you see some hourly crons generating some requests (not a lot) and more particularly at the 31st minute is an hourly mongodump (the one fetching a lot of documents in this chart I suppose). So the history of these documents is:
Here are the collections stats, TLDR there's a lot of small and very similar records (21M).
Let me know if you need anything else! | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Bruce Lucas (Inactive) [ 21/Nov/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks for the report Adrien. Can you help me with some background information and context regarding the workload. Here's what I see in the ftdc data:
The batch job in question seems to run from A to B (about 11:05 to about 11:35 (under 4.0, longer under 4.2 because the deletes are slower). It seems to consist of a lot of deletes followed by a lot of inserts, and there may also be some finds during both the deletes and the inserts (based on document returned). This seems to be consistent with what I see in your cron logs. At the same time there appears to be a constant stream of background activity, mostly updates, punctuated by some other jobs that run at hourly intervals. Can you confirm or correct the above? What is the history of the documents being deleted - were they inserted by the previous instance of this cron job, by the periodic jobs inserting documents every hour, or have they been in the collection for a long time? Have the documents that were deleted been updated since inserting? Is the daily cron job in question operating on its own collection independent of the other activity on the system? Are the deletes distributed randomly in the collection or are they sequential? Also can you attach collection stats for the collection in question so I can get an idea of the number of indexes, size of collection, and size of documents. Are the documents generally all about the same size, or is there a wide range of variation? What I have seen so far is that during the deletes there is much higher cache pressure and eviction activity, which I believe explains the higher CPU and lower delete rate. I'm also seeing about 2x the amount of dirty data generated in the cache per delete under 4.2, which could possibly explain the higher cache pressure. I'm hoping that clearer picture of the workload and history of the documents might help me understand the reason for this. It may also help us reproduce the problem in isolation. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Adrien Jarthon [ 21/Nov/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks, I uploaded the diagnostic data and the two requests logs related to this script running against 4.0.13 and 4.2.1 | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Danny Hatcher (Inactive) [ 21/Nov/19 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
As requested, here is an uploader link: https://10gen-httpsupload.s3.amazonaws.com/upload_forms/550e137f-ce8e-4cf8-8123-47d82d1d3b7e.html |