U4-7870 - Performance degradation

Created by Marc van de Wert 01 Feb 2016, 09:59:56 Updated by Shannon Deminick 02 Feb 2016, 12:26:58

I upgraded to Umbraco 7.3.6, and after the upgrade to version 7.3.6 the performance of my website is horrible. Even after everything is cached (my own cache of product information etc, the cache of umbraco itself is turned off because of development purposes). When I look at the output of /Trace.axd I see that calling macro(s) that took around one second to complete now take +17 seconds to complete.

I've attachted the output of my Trace.axd from before and after I upgraded to version 7.3.6 below.

Please mind that there is no code changed, except that umbraco is upgraded.

Version 7.3.5:

Request Details

Session Id: Request Type: GET Time of Request: 01/02/2016 10:55:59 Status Code: 200 Request Encoding: Unicode (UTF-8) Response Encoding: Unicode (UTF-8) Trace Information

Category Message From First(s) From Last(s) UmbracoModule Umbraco request begins UmbracoModule Umbraco request confirmed 0.209598 0.209598 renderMacro Render Macro: Main navigation, type: PartialView, cache: 0) 1.900855 1.691257 umbracoMacro Partial View added () 1.906609 0.005754 renderMacro Render Macro: Sub navigation, type: PartialView, cache: 0) 3.662574 1.755965 umbracoMacro Partial View added () 3.662622 0.000048 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 4.382283 0.719661 umbracoMacro Partial View added () 4.382322 0.000039 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 5.951652 1.569330 umbracoMacro Partial View added () 5.951692 0.000040 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 5.964104 0.012412 umbracoMacro Partial View added () 5.964136 0.000032 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 5.976801 0.012665 umbracoMacro Partial View added () 5.976834 0.000032 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 5.987478 0.010644 umbracoMacro Partial View added () 5.987510 0.000033 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 6.002010 0.014500 umbracoMacro Partial View added () 6.002045 0.000035 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 6.003486 0.001440 umbracoMacro Partial View added () 6.003511 0.000025 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 6.012764 0.009253 umbracoMacro Partial View added () 6.012791 0.000027

Version 7.3.6:

Request Details

Session Id: Request Type: GET Time of Request: 01/02/2016 10:47:01 Status Code: 200 Request Encoding: Unicode (UTF-8) Response Encoding: Unicode (UTF-8) Trace Information

Category Message From First(s) From Last(s) UmbracoModule Umbraco request begins UmbracoModule Umbraco request confirmed 0.171633 0.171633 renderMacro Render Macro: Main navigation, type: PartialView, cache: 0) 1.689967 1.518334 umbracoMacro Partial View added () 1.697413 0.007447 renderMacro Render Macro: Sub navigation, type: PartialView, cache: 0) 19.695047 17.997633 umbracoMacro Partial View added () 19.695091 0.000045 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 26.483367 6.788275 umbracoMacro Partial View added () 26.483406 0.000040 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 28.629613 2.146207 umbracoMacro Partial View added () 28.629655 0.000042 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 28.646423 0.016768 umbracoMacro Partial View added () 28.646461 0.000038 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 28.658420 0.011959 umbracoMacro Partial View added () 28.658457 0.000037 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 28.690973 0.032516 umbracoMacro Partial View added () 28.691016 0.000043 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 28.718268 0.027252 umbracoMacro Partial View added () 28.718309 0.000041 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 28.729837 0.011529 umbracoMacro Partial View added () 28.729874 0.000036 renderMacro Render Macro: Product item small, type: PartialView, cache: 0) 28.739879 0.010006 umbracoMacro Partial View added () 28.739916 0.000037

4 Attachments

Download Event.log

Download UmbracoTraceLog.PDC-DEV08.txt

Download MiniProfiler.zip

Download 7.3.6-patch1.zip

Comments

Vincent Baaij 01 Feb 2016, 10:23:52

I can confirm there's something wrong with 7.3.6. An upgraded customers site was running fine performance wise before the upgrade and almost set the processor on fire and was not performing anymore after upgrading to 7.3.6. After setting the bin folder back to 7.3.5 everything began running normal again.


Shannon Deminick 01 Feb 2016, 11:12:46

Hi is it possible you can send me your source so I can profile it ? You can mark it visible to HQ only, or if you have a simple way to reproduce we will have a look asap.


Marc van de Wert 01 Feb 2016, 11:20:23

I it's not possible to send the source, because of sensitive information; products and customer information. And if I could then it would not be possible to send you the code and the data that is associated with it because the DB's are to large (+10 GB for test product data alone)

Is there any other way I can help you?


Shannon Deminick 01 Feb 2016, 11:25:57

I need to know how to replicate this performance issue. If it's as simple as a single macro not working as well in 7.3.5, then what is in that macro? Code samples? etc... without being able to replicate, i can only guess and that's not going to be helpeful


Marc van de Wert 01 Feb 2016, 11:32:11

I hope this helps:

I use the grid. The only difference is the upgrade to 7.3.6.

Macro code: @inherits Paradigit.Base.SDK.BuildingBlocks.Web.Mvc.BasePartialViewMacroPage

@if (Model.MacroParameters.ContainsKey("cssclass")) { <div class="@Model.MacroParameters["cssclass"].ToString()"> @Html.Action("GetSubnavigation", "UtilitySurface", Model.MacroParameters.ToRouteValueDictionary())

} else { @Html.Action("GetSubnavigation", "UtilitySurface", Model.MacroParameters.ToRouteValueDictionary()) }

Extension method: public static class IDictionaryExtensions { ///

/// To the route value dictionary. /// /// The parameter. /// public static RouteValueDictionary ToRouteValueDictionary(this IDictionary<string, object> parameter) { RouteValueDictionary routeValues = new RouteValueDictionary();

        foreach (string parameterKey in parameter.Keys)
        {
            routeValues.Add(parameterKey, parameter[parameterKey]);
        }

        return routeValues;
    }
}

UtilitySurfaceController: ///

/// Gets the subnavigation. /// /// The menu structure. /// [ChildActionOnly] public ActionResult GetSubnavigation(int menuStructure) { Paradigit.Ecommerce.Models.MacroPartial.SubNavigationModel model = new Paradigit.Ecommerce.Models.MacroPartial.SubNavigationModel(); model.NavigationMenuId = menuStructure;

        return PartialView("Subnavigation", model);
    }

Partial view: @inherits Paradigit.Base.SDK.BuildingBlocks.Web.Mvc.BaseUmbracoViewPage<Paradigit.Ecommerce.Models.MacroPartial.SubNavigationModel>

@{ Umbraco.Web.Models.DynamicPublishedContent assignedContentNode = Umbraco.Content(Model.NavigationMenuId);

IEnumerable<IPublishedContent> childNodes = assignedContentNode.Children()
    .Where(d => d.DocumentTypeAlias == "NavigationItem");

}

{monospace}


Vincent Baaij 01 Feb 2016, 11:52:17

We also use the grid in our site. As mentioned that works fine on 7.3.5.

One thing we found is that the LeBlender.Extensions.Helper chockes on the GetLeBlenderControllers method. It tries to scan ALL assemblies for an interface and generates an exeption on (in our case) the Microsoft SignalR dll. It can therefore not cache the result (a list of all LeBlender controllers) and scans all bineries again on the next request.


Shannon Deminick 01 Feb 2016, 15:00:41

I'll investigate this evening and should have a solution very soon if I can reproduce. As for le blender, I'm I sure about how it works but I won't be running any tests with it. @Marc, are you also using this package?


Marc van de Wert 01 Feb 2016, 15:01:48

Nope, I'm not using that.


Shannon Deminick 01 Feb 2016, 15:06:26

Ok thanks, that makes it a bit easier for me so I don't need to test that. But @vincent, I'd urge you to contact leblender devs of you know of an issue with it. Scanning assemblies is super expensive, we do this in the core but in a very particular way with caches and the PluginManager which all devs should use if they are scanning plugins


Vincent Baaij 01 Feb 2016, 15:09:37

@Shandem Will do!


Jay Larbes 01 Feb 2016, 15:21:20

Just adding a "me too" to this thread. We have a project that we upgraded to 7.3.6 yesterday (1/31), and now every page load takes 30-40 seconds. FYI, this is a project that is in the umbraco.io UAAS hosting. The project name is "Home Helpers" if you want to review source code or database.

A little background about the site: it has a parent site and 300 locations. Each location has its own mini-site underneath the parent. So, we basically have 300 mini-sites running under one Umbraco project - each mini-site has 5-10 pages.


Shannon Deminick 01 Feb 2016, 15:31:43

Thanks for reporting, the more info I've have the easier/faster I'll fix/patch.

I assume this perf degradation is on each request? Not just the first request on start-up?


Marc van de Wert 01 Feb 2016, 15:32:01

At first I thought the issue was in my partial view, in there I retrieve a lot of data from Umbraco and render it in not the most efficient way, but this isn't the issue I've measured the rendering of the actual partial view in my controller like:

Stopwatch stopwatch = new Stopwatch(); stopwatch.Start();

        PartialViewResult result = PartialView("Subnavigation", model);

        stopwatch.Stop();
        TimeSpan ts = stopwatch.Elapsed;
      
        return result;

And the elapsed time is: stopwatch.Elapsed = {00:00:00.0000021}

It seems to be something after rendering the view.


Marc van de Wert 01 Feb 2016, 15:32:42

Yes the performance degradation is on each request, every time each time.


Shannon Deminick 01 Feb 2016, 15:32:51

Another question is : how many doc types so you have?


Vincent Baaij 01 Feb 2016, 15:33:23

for us it is with every request, not just on startup


Jay Larbes 01 Feb 2016, 15:33:25

@Shandem Correct - this degradation is on every request, not just the first request on start-up.


Marc van de Wert 01 Feb 2016, 15:34:51

At the moment I have 43 document types.


Vincent Baaij 01 Feb 2016, 15:35:31

@Shandem we have 30 doctypes


Jay Larbes 01 Feb 2016, 15:35:54

72 document types here.


Shannon Deminick 01 Feb 2016, 15:36:01

Another question: Is the performance any different on dev vs live? (i.e. When debug is on vs off in the web.config)


Marc van de Wert 01 Feb 2016, 15:38:02

No it's all the same, debug or release. I have a release build with debug = off on Azure and that deployment has exactly the same issue.


Jay Larbes 01 Feb 2016, 15:40:00

I agree with Marc. No difference.


Vincent Baaij 01 Feb 2016, 15:41:13

I also agree. No difference


Shannon Deminick 01 Feb 2016, 15:42:07

Ok, sorry to bombard with questions but this all helps tremendously. I'm on the train now and will have a patch available tonight if I can replicate.

Anything strange in your log files? Anything about syncing instructions? There is a file in your app data folder under dist cache called lastsynced ( or similar), can you check if this integer value equals the Max is in the db instructions table?


Vincent Baaij 01 Feb 2016, 15:45:55

@Shandem lastsynced nr == max umbracoCacheInstruction. Haven't kept logs but remember seeing sync times being very low (8~15 ms). It's one server btw


Shannon Deminick 01 Feb 2016, 15:52:12

One thing you could try is in your dev env add umbdebug=true as a query string. This should show the mini profiler (if you are using standard umb views),the you cab expand it and click share which will show you the profile output in html, then you can attach it here


Marc van de Wert 01 Feb 2016, 15:52:57

@Shandem I've attached all the log files I have, I hope this helps. Yes the integer in the DB is exactly the same as in the in my case "LMW3SVC1ROOT-lastsynced.txt" file.


Marc van de Wert 01 Feb 2016, 16:00:38

@Shandem I've attached the extreme cases of the miniprofilter.


Shannon Deminick 01 Feb 2016, 17:11:19

Hi @mvdwert

I've had a quick look at the mini profiler report attached but that really has no information on this particular problem - since those profiles are in the back office. Can you run the profiler on the page(s) that has the issue? The only thing in your log files that seems relevant is the warnings:

System.InvalidOperationException: Cannot return the IPublishedContent because the UmbracoHelper was constructed with an UmbracoContext and the current request is not a front-end request.

Does this get logged whenever the page loading time is slow?


Shannon Deminick 01 Feb 2016, 18:40:40

Hi all,

I have found the issue. Working on a solution tonight, will have a patch of some sort some time tomorrow. I'll report back with details then.

Thanks for your help so far.


Shannon Deminick 02 Feb 2016, 00:54:56

Hi all,

I've attached a patch that you can use if you need to solve this immediately. We'll need to release a 7.3.7 asap to ensure not too many others are affected by this.

Here's the details:

With 7.3.5 we create an optimized way of caching entities at the repository level to fix a performance issue for when there was a large amount of data, we did this by implementing something called Cache Policies and Isolated Caches. The problem was due to storing a large number of cached instances in a single dictionary cache. This meant a lot of enumerating this dictionary searching for matching keys. (see: http://issues.umbraco.org/issue/U4-7558) The performance problems in question were regarding repositories that get queried often using the GetAll. So it turns out it would be better to simply cache the whole collection as a single list instead of individually by Id - meaning less items in the dictionary. The specific repositories were: Domains, Languages, Public Access, Template Repository - since all of these are required for routing and rendering content at all times

7.4.0 is also being built right now and by default we build strongly typed models which requires having access to all of the content type information so we implemented the same policies for the content type repositories that we had in 7.3.5, when we built 7.3.6 we determined which tasks should be backported and this was one of them since it seemed to make a lot of sense. We also require content type data to render front-end content, because this is how we can determine which value converters are required for each property value, etc... It seemed like a simple win to include the new cache policy for content types and remove the existing statically cached published content type data cache since we didn't think double caching was necessary... this was a bad idea.

What I failed to take into account was:

  • The new cache policy for content types will cache all of them in a list but when we put any item in or take any item out of the repository caches, the object needs to be Deep Cloned. Since the IContentType model is rather large and complex, deep cloning this isn't super fast
  • Since the published content properties need to the content type data all of the time, this meant that for every property rendered it needs to lookup it's associated property type (deep cloning)
  • Since I removed the front-end property type cache, now we also need re-lookup the value converters for the property type

So this issue is completely my own fault, please accept my apologies, this was a case of being naive and trying to easily optimize memory & performance and ending up doing the opposite.

Some good has come out of this though!! I have found some real optimizations:

  • The DeepCloneHelper that assists in performing the deep cloning of all entities in and out of the repository cache was only caching the initial type lookups when it should have been caching the enumerable type lookups too. I've fixed this and now it performs twice as fast! This is great news since this is used by nearly every repository/model in Umbraco when using the Services.
  • I found a minor bug in the published property type cache that is now fixed (https://github.com/umbraco/Umbraco-CMS/commit/d9374c34d162f67b05efdc65b9af8994d03f06ad#commitcomment-15812074)
  • I found/fixed a couple minor bugs in the FullDataSetRepositoryCachePolicy
  • I optimized how FullDataSetRepositoryCachePolicy works when it deep clones, as noted previously this would deep clone all items in the list when storing in the cache and then again each time when retrieving from the cache. We can save some performance by not deep cloning each item out of the cache when we are filtering the list result to only a single item - so we filter first, then deep clone the single item.
  • Added unit tests to support

If anyone is willing to test, just drop these DLLs into your bin that you have 7.3.6 installed and please let mek know the result.

Thanks!


Shannon Deminick 02 Feb 2016, 00:59:47

@jlarbes I've tested this patch on your site (on my local machine) and it now performs the same as it did on your previous version without issue.


Per Osbeck 02 Feb 2016, 07:09:29

I can confirm that the patch solves the issue for us. Performance is back to normal ~500ms instead of 7s.

Thanks!


Marc van de Wert 02 Feb 2016, 08:13:03

I can also confirm that the batch solves the issue at hand, and the performance is the same as in version 7.3.5.

@Shandem Apologies are accepted, you were trying to improve Umbraco by improving the cache, but unfortunately something broke. No problems, I am glad it's fixed now and I'm glad that Umbraco has employed such a talented developer. Thank you!


Jonas Boye 02 Feb 2016, 08:20:28

Solved for me as well. Thanks for the effort @Shandem!


Arjan Woldring 02 Feb 2016, 10:30:25

@Shandem Nothing but respect how well you handled this issue/situation. Great job! Thanks!


Bartosz LadziƄski 02 Feb 2016, 12:03:56

The performance is back to ok after applying the patch, but instead I'm being spammed by my logging service with "Thread was being aborted" and "A task was cancelled" error messages in various parts of code.

System.Threading.Monitor in ObjWait Thread was being aborted.

System.Threading.Monitor in Enter Thread was being aborted.

System.Reflection.RuntimeAssembly in GetExecutingAssembly Thread was being aborted.

System.AppDomain in GetId Thread was being aborted.

System.Runtime.CompilerServices.TaskAwaiter in ThrowForNonSuccess A task was canceled.

The places of occurrences of the exceptions seem to be a bit random.


Shannon Deminick 02 Feb 2016, 12:26:58

@Slowacki the performance should be back to what it was previously, it should certainly not be any worse. We'd need a full stack trace of the errors you are getting, but you should probably open a new ticket if it's something you can reproduce.


Priority: Critical

Type: Bug

State: Fixed

Assignee:

Difficulty: Normal

Category:

Backwards Compatible: True

Fix Submitted:

Affected versions: 7.3.6

Due in version: 7.3.7

Sprint: Sprint 8

Story Points:

Cycle: