U4-6292 - CPU Keeps Getting Pegged Every Few Hours

Created by Nicholas Westby 19 Feb 2015, 01:34:58 Updated by Connie DeCinko 09 May 2016, 17:58:04

Relates to: U4-7050

Every few hours (somewhat random intervals), the CPU on my server gets pegged until I restart the application pool: !cpu.png!

The only reason it's around 70% rather than 100% is because I set IIS to restrict that application pool so it doesn't use more than 70% of the CPU (this is a CPU throttling feature IIS offers). Here is what New Relic shows as a hot spot: !new-relic.png!

I also used dotTrace to do some profiling with similar results: !dot-trace.png!

The issue seems to be around this code: https://github.com/umbraco/Umbraco-CMS/blob/dev-v7/src/Umbraco.Core/Models/EntityBase/TracksChangesEntityBase.cs#L44

There doesn't seem to be anything wrong with that code in particular, so my guess is that it's being called over and over (perhaps in an infinite loop). Here's an alternate type of trace I did in dotTrace that shows the same thing: !dot-trace-alt.png!

I'm not sure why I'm seeing this, but maybe it has something to do with that fact that a couple people are using the same login, or maybe it's because I changed the password for this user at some point (I mention that because this issue seems to be related to users, and Umbraco 7.1.8 has an issue where the password change doesn't take effect until I recycle the app pool).

Note that the Umbraco backend becomes completely unusable when the CPU is pegged like this (i.e., it can take minutes for a page to load, if it does at all, and saving never seems to finish). The frontend of the website is also extremely slow. The site is only on staging now, so there are under 5 users, but it will be going live soon.

I have profiling information from dotTrace if that would help (I can share them privately with the Umbraco team).

Here's a related Umbraco forum thread (it was about a memory issue that isn't really a problem, but I'm just linking to it for reference): https://our.umbraco.org/forum/core/general/61448-Memory-Climbs-2GB-in-11-Hours-in-Umbraco-718

8 Attachments

Comments

Nicholas Westby 20 Feb 2015, 06:02:55

Note to self: This may be related to http://issues.umbraco.org/issue/U4-4259


Nicholas Westby 20 Feb 2015, 06:26:18

Hmmm, I wonder if Umbraco.Core.Models.EntityBase.TracksChangesEntityBase.SetPropertyValueAndDetectChanges could be problematic. It checks if two properties are equal to mark items as dirty. In the case of Umbraco.Core.Models.Membership.UserType.Permissions, that property is IEnumerable... if you compare two IEnumerables as objects, I wonder if that just checks for reference quality and always returns true (since according to the stack trace that occurs in the context of a deep clone that involves creating new collections). If that initiates an "on change" event that has a listener that does the same, it could cause an infinite event loop. That's just a wild theory though... I may have to recompile Umbraco to add some diagnostic info to better track this down.


Shannon Deminick 20 Feb 2015, 08:06:53

My first suggestion is to upgrade to the latest 7.x and see if that solves your issue


Nicholas Westby 21 Feb 2015, 05:16:53

Upgraded today to 7.2.2. Will see how things work out on Monday.


Nicholas Westby 23 Feb 2015, 18:45:04

Looking at the stack trace, my theory about IEnumerables being erroneously marked as changed seems plausible. I very much doubt User.DefaultPermissions was actually changed, yet from the stack trace it is being detected as changed and is firing the OnPropertyChanged event. Here is the original implementation of TracksChangesEntityBase.SetPropertyValueAndDetectChanges: !detect-original.png!

Notice that it is using object.Equals even for instances that may be collections. I would think that for collections, you'd want to use something like Enumerable.SequenceEquals. I wasn't able to get that working on short notice, but maybe something like this would be appropriate (it's not optimal and it's untested, but it's just for demonstration purposes): !detect-suggestion.png!

Basically, the idea is that it's checking if they are collection types. If they are, it compares the contents of those collections rather than just checking if the collections are the same collection instance. Not sure if this would fix my issue, but it's a starting point, and may potentially fix other unknown issues.


Nicholas Westby 23 Feb 2015, 19:02:37

Hmmm, slight bug in that code (i the counts are not equal, it should be detected as a change). You get the idea though.


Shannon Deminick 23 Feb 2015, 19:06:05

Interesting indeed, I will have a look later this week (am travelling back to australia tomorrow), but yes, it should take into account different object types for sure. I'll bump this to 7.2.3.


Shannon Deminick 23 Feb 2015, 19:09:14

For collection changes though it might be that we need to deal with those as observable collections since we are doing that else where, I'll have a look through the codebase to see that is a settable enumerable property and how that might affect things.


Nicholas Westby 23 Feb 2015, 21:14:29

FYI, I just confirmed that it's also happening on Umbraco 7.2.2.


Shannon Deminick 23 Feb 2015, 21:27:33

Thanks, hopefully can get this replicated this week


Jerry Federspiel 24 Feb 2015, 21:08:20

I have also experienced this issue, and see largely similar stack traces in procdumps (via user login rather than an AuthorizeAttribute'd controller action).

Apologies if this is obvious or obviously wrong, but:

The first thing we do in User.DeepClone() is an object.MemberwiseClone() which gives both the original User u1 and the new User u2 the same data in their fields. This includes references to the same change-tracking dictionaries. Then we start poking stuff into their properties with DeepCloneRefProperties, which does not make new dictionaries because the change tracking dictionaries are fields and have no corresponding properties.

Incidentally, the property changes that DeepCloneRefProperties is making appear to trigger change notifications, which seems unnecessary while the object is still being cloned and may represent a data race risk as long as the change tracking dictionaries are shared. I may be missing something, but change-tracking functionality does not seem to be appropriate during the cloning operation, because while we are changing the internal representation of u2 during cloning, we are not making changes to u2 that represent a semantic or behavioral change in u2. For this reason, it may be appropriate to check for IDeepCloneable and collection types among the fields and deep clone those, bypassing the properties and their attendant change-tracking altogether.

At the end of User.DeepClone(), we say u2.ResetDirtyProperties(false). This gives u2 a new Dictionary for u2._propertyChangedInfo, but does not give it a new _lastPropertyChangedInfo, so that is still shared between u1 and u2 (and so on, for every subsequent object cloned from u1) unless someone calls ResetDirtyProperties(true) at some point.

The fact that there are several users using the same login may be significant if they are logging in or performing authorized actions at nearly the same time, because then you've got a couple different threads accessing the same _lastPropertyChangedInfo (and until the cloning process gets to ResetDirtyProperties, the same _propertyChangedInfo as well).


Nicholas Westby 27 Feb 2015, 20:17:33

@Shandem Any word on this? I am releasing a website Tuesday affected by this. If there isn't an official fix, I'll have to put in my somewhat uninformed workaround, which I'd rather not do.


Shannon Deminick 28 Feb 2015, 01:50:11

Haven't had a chance to look. The fix will only be available in 7.2.3 (or nightlies once its done) so you'll probably need to do your work around anyways if you are going live on Tuesday. Should have it fixed next week at some stage.


Shannon Deminick 03 Mar 2015, 07:37:01

I've updated the deep cloning logic in rev: 8905878a8785a71742dbce7441d445bf44bd3d24 so that change tracking is not enabled while cloning... which makes a ton of sense and will speed things up a little too. I've also change the logic to ensure the dictionaries are reset for the cloned instance to it's own refs before the cloning process. This will solve the behavior illustrated by @jerryfederspiel so that's a step in the right direction. I'm going to look at any collections that we use SetPropertyValueAndDetectChanges with since IIRC this method was never intended to be used for collections which should be dealt with differently.


Shannon Deminick 03 Mar 2015, 07:58:05

I've found 6 places that we use this method with collections, so need to see if we enabled this method to work with collections or use observable collections. I'll report back tomorrow once I have the answer.

I've also determined that there's only one class that listens to the actual PropertyChanged event and that is the macro model to track it's own changes, so there shouldn't be any infinite loops with regards to setting a property, detecting a change, raising and event, handling the event and changing the property again.


Shannon Deminick 05 Mar 2015, 06:16:12

Hi @Knickerbocker ,

I've made a few commits that you might be interested in:

8905878a8785a71742dbce7441d445bf44bd3d24 834b780d8ee8bab3f0003a06ac0c00e8b660fcc5 9a042fbbdf5c785356572c1a239f4c4cc63007c3 46212904ef797f398aba16cd3ed6f97c2745b77a

I've update the deep cloning logic (as mentioned above), I've removed change tracking entirely from the User.DefaultPermissions since that should be tracked anyways (it actually shouldn't have a setter at all). I've changed the SetPropertyValueAndDetectChanges to have 2 overloads. If you call this method with an enumerable without specifying an IEqualityComparer it will throw an exception. I've updated all models that use this method with enumerable to use a custom equality comparer which uses a new enumerable extension method called UnsortedSequenceEqual.

Since this issue is quite hard to replicate at-will, it would be great if you could review this code, perhaps cherry pick these commits into your project and see if that fixes the issue. Otherwise if you have another suggestion of how I can determine if this fixes it please let me know. I think based on the deep clone logic changing and updated change tracking that you won't see this issue anymore.


Nicholas Westby 10 Mar 2015, 05:29:54

Will see if I can find some time to check on this soon (have been out of town for a few days).


Shannon Deminick 17 Mar 2015, 07:26:42

Hi @KKnickerbocker , please let me know when you've had a look so I can either fix more or close this :)


Nicholas Westby 17 Mar 2015, 13:52:43

@Shandem I actually haven't seen this happen since I launched the site and had everybody use their own logins rather than a single shared login. So, maybe just mark it as fixed and I'll upgrade to 7.2.3 when it comes out. If I have any issues, I'll let you know and we can reopen this.


Shannon Deminick 17 Mar 2015, 23:09:07

sure thing, i think with the core changes, there will be a vast improvement since everything you guys mentioned in this thread made sense and the code definitely needed a bit of TLC in that area.


Nicklas Gavelin 20 Mar 2015, 06:59:14

Does this also affect the 6 branch? (As we've had some trouble with CPU getting stuck on Umbraco 6.1.6 and 6.2.1). And if it affects the 6 branch it would be great with a release fixing this issue even if the 6 branch is no longer maintained as it's a pretty serious bug.


Nicholas Westby 20 Mar 2015, 13:58:02

Nicklas, I also had CPU issues on 6.1.6. Never did have a chance to resolve that issue (client took over the site), but I believe that issue was eventually resolved in an Umbraco release. I can't seem to find the YouTrack issue for that though (I vaguely recall posting a reply in the Umbraco forums about experiencing that issue, but I can't seem to find that reply either).

I have no idea if this issue applies to the Umbraco 6 branch.


Oleg 01 Sep 2015, 01:30:19

Hi guys, I can see this issue has been raised a while ago, but I found it only now. Just wanted to let you know that this exact issue happens in 6.2.5 and is crippling our production environment pretty badly. We have multiple incidents every day ever since we upgraded from 6.1.5 to 6.2.5 two-three weeks ago. NewRelic trace looks extremely similar to what Nicholas Westby posted back in Feb when he raised this issue. Are you guys able to advise what we can do about this? I am seriously considering downgrading back to 6.1.5.

Thank you guys! Oleg.


Oleg 01 Sep 2015, 01:41:10

Is this related to U4-4259?


Erik Thijssen 21 Mar 2016, 08:15:05

Hi Guys,

Is there any news about the release of 6.2.6.? We need to upgrade several 6.2.5. installations. Status show completed but it's not available for either download or NuGet https://our.umbraco.org/contribute/releases/626/


Shannon Deminick 21 Mar 2016, 09:45:23

we're waiting on testing feedback and then we'll release.


wtct 22 Apr 2016, 13:56:11

This issue is linked in latest v6 release page:

https://our.umbraco.org/contribute/releases/626/

I'm preparing for upgrate from 4.7.1 to 6.2.5 and I made some modification for 6.2.5. Now I see there is 6.2.6 version but I can't find branch associated with this version here:

https://github.com/umbraco/Umbraco-CMS

I have own forked repository:

https://github.com/wtct/Umbraco-CMS

with upstream set to:

https://github.com/umbraco/Umbraco-CMS

I don't see any changes at branch 6.2.5 associated with this issue.

Please help me to find brach with version 6.2.6 (upgraded 6.2.5 version with this issue) which I can merge to 6.2.5 version of my forked repo.


Shannon Deminick 22 Apr 2016, 14:12:41

I dont even think this affects 4.x versions


wtct 22 Apr 2016, 14:32:52

Version 4.7.1 is outside of interest :)

I'm just upgrading from 4.7.1 to 6.2.5 but I see that there is newer version 6.2.6.

This issue is linked at this page under Issues & Tracks header:

https://our.umbraco.org/contribute/releases/626/

So this issue affects 6.2.6 version not 4.7.1.

Now I need to find 6.2.6 branch.


Nicholas Westby 23 Apr 2016, 16:11:28

I agree, that is a bit strange. Usually there is a tag for each release, but I don't see one for 6.2.6:

!tags.png!


Shannon Deminick 23 Apr 2016, 16:13:21

I'm sure @sebastiaan can let us know on Monday.


wtct 25 Apr 2016, 08:10:50

@Shandem I hope :)


wtct 28 Apr 2016, 10:56:53

@Shandem Unfortunately @sebastiaan is on vacation or doesn't see our discussion. Could you help? It is very important for me to download source code of 6.2.6 version.


Sebastiaan Janssen 28 Apr 2016, 11:09:13

It's tagged now. https://github.com/umbraco/Umbraco-CMS/releases/tag/release-6.2.6


wtct 28 Apr 2016, 12:28:08

@sebastiaan Thanks a lot!

I have just created new branch 6.2.6 in my forked repo by merging this tag into branch 6.2.5.


Connie DeCinko 09 May 2016, 17:58:04

Since upgrading to 6.2.6 we are no longer able to save templates or XSLT which contain jQuery (http://issues.umbraco.org/issue/U4-8427). The server spins out of control and the XSLT editor displays a message about not being able to save the file.


Priority: Show-stopper

Type: Bug

State: Fixed

Assignee: Shannon Deminick

Difficulty: Normal

Category:

Backwards Compatible: True

Fix Submitted:

Affected versions: 7.1.8, 7.2.2

Due in version: 7.2.3, 6.2.6

Sprint:

Story Points:

Cycle: