Performance: Degradation in throughput v13 vs 15

[enkelmedia]

Which Umbraco version are you using?

15.3.0

Bug summary

While testing out v15 with a "real world database" from one of our projects I'm noticing quite a difference in throughput between v13 and v15.

I've taken the database from a v13 website and hooked it up with two clean Umbraco-projects, one for v13 and another for v15. In the Umbraco 15 version I configured the DocumentBreadthFirstSeedCount to 50000 to get all content into the cache.

I'm using the exact same views and code on both versions, it's basically:

• Some traversing to create a menu based on the root node and it's children.
• A container node with around 2500 descendants (in different depth of the tree).

The view that I'm testing with is a simple cshtml file that just loops over and render nodes with links.

To even get close to comparing the performance, I first had to apply this hack: #18869

After this I ran a couple of simple load tests to compare the throughput.

Umbraco 13.7.2
Median load time: 9ms
Request per second: 343

Umbraco 15.3.0
Median load time: 28ms
Request per second: 131

I'm also noticing quite a different behavior when it comes to GC-pressure:

Umbraco 13:
While the memory usage goes up, the GC-pressure is not that high.

Umbraco 15:
In Umbraco 15, the GC runs almost all the time.

I'm not sure if all these test are "state of the art" but I'm confident that there is a big difference in the "out of the box" performance between the versions and I really think that this is something that is important and that should be addressed in upcoming releases.

Specifics

No response

Steps to reproduce

See above

Expected result / actual result

No response

---

This item has been added to our backlog AB#51952

[github-actions]

Hi there @enkelmedia!

Firstly, a big thank you for raising this issue. Every piece of feedback we receive helps us to make Umbraco better.

We really appreciate your patience while we wait for our team to have a look at this but we wanted to let you know that we see this and share with you the plan for what comes next.

• We'll assess whether this issue relates to something that has already been fixed in a later version of the release that it has been raised for.
• If it's a bug, is it related to a release that we are actively supporting or is it related to a release that's in the end-of-life or security-only phase?
• We'll replicate the issue to ensure that the problem is as described.
• We'll decide whether the behavior is an issue or if the behavior is intended.

We wish we could work with everyone directly and assess your issue immediately but we're in the fortunate position of having lots of contributions to work with and only a few humans who are able to do it. We are making progress though and in the meantime, we will keep you in the loop and let you know when we have any questions.

Thanks, from your friendly Umbraco GitHub bot 🤖 🙂

[enkelmedia]

I spent some more time digging into this issue and I might have found something worth looking into.

The test case that I have is rendering a menu and a list of content, totally somewhere around 800 nodes are used during the request. I know that this is probably not the "typical use case" but it does bring some underlying issues to the surface.

As far as I understand, each time a content node is fetched from the new HybridCache, a ContentCacheNode is returned from the cache, passed to some factories that will create a new ContentNode and then call the ctor of PublishedContent to create an new instance.

Looking at some profiling, most of the time in my request is spent creating these PublishedContent instances.

Since the DocumentCacheService is used to fetch content when traversing the tree, each call to GetNodeAsync(Guid key, bool preview) will go trough the process of fetching ContentCacheNode from memory or L2-cache and then create an instance of PublishedContent. The same thing happens when .Url() is called, even if the same node was already fetched and passed trough the factories this process would be repeated. Notice in the trace above that the ctor of PublishedContent was called over 7000 times during this request.

I made a very hacky test using AppCaches.RequestCache to see what would happen if I would cache the PublishedContent for the duration of the request (see example below). This reduced the number of new PublishedContent-instances to half.

The load time for this particular page is still 250-500% slower than it used to be in Umbraco 13 (the exact same code). (With my other hack from #18869 applied as well).

I'm thinking that it would be very beneficial to explore options to improve this, I don't know the exact constrains around PublishedContent and HybridCache but some ideas and thoughts:

Ideally the IMemoryCache would hold instances of ´PublishedContent´ and HybridCache should just use ContentCacheNode when serializing to IDistributedCache (don't know if that is even possible). If PublishedContent needs access to request-bound information like VariationContext something could fetch from the memory cache and update the cached instance with the request-bound information. This would avoid the allocation of new instances of PublishedContent and ContentNode on each request.

Also, something similar to my "request-cache"-hack below could be implemented to avoid re-creating the same PublishedContent-instance in the context of the same request. I'm aware that not all calls to DocumentCacheService will be in the context of a HttpRequest (Background jobs etc) but I don't know if there is any other caching mechanism that can be used for this.

I would be more then happy to provide more information should it be needed.

Code from the hacked DocumentCacheService

private async Task<IPublishedContent?> GetNodeAsync(Guid key, bool preview)
{
    var cacheKey = GetCacheKey(key, preview);

    var node = _appCaches.RequestCache.GetCacheItem<IPublishedContent?>("pc-" + cacheKey, () =>
    {
        var contentCacheNode = this.GetContentCacheNode(cacheKey, key, preview).ConfigureAwait(false).GetAwaiter().GetResult();

        // We don't want to cache removed items, this may cause issues if the L2 serializer changes.
        if (contentCacheNode is null)
        {
            //await _hybridCache.RemoveAsync(cacheKey);
            return null;
        }

        return _publishedContentFactory.ToIPublishedContent(contentCacheNode, preview).CreateModel(_publishedModelFactory);

    });

    return node;

}

[Migaroez]

Hey @enkelmedia I have spend some time investigating this and have come up with the following findings.

Both the (old) nucache and the new hybridcache system use intermediate objects as IPublishedContent is more than a pure data object and it also holds data relative to the current execution context so it would be impossible to cache it across requests.

I have tried to figure out where the GC pressure came from and even though I have no hard data proof i do have the following 2 videos. Both videos show you the startup of the app with an empty view on the default page and then opening of the Crazy menu page (code below) and multiple refreshes of that page.

The first video shows the default configuration of 100 nodes preseeded. (menu page loads 3993 nodes)
The second video shows the cache preseeded with all nodes as I have less than 10000. In the second video you can clearly see that the GC happens After the empty page is loaded and thus the cache has been seeded but before I load the crazy menu page. This tells me that the GC is a result of the seeding instead of the fetching of the data. Which might tells us that this is something that is caused by the hybrid cache as the underlying fetch code (DB access) has remained the same between the 2 systems.

umb-issue18892.default.mp4

umb-issue18892.preseed.mp4

@using System.Diagnostics
@inherits Umbraco.Cms.Web.Common.Views.UmbracoViewPage<Umbraco.Cms.Web.Common.PublishedModels.Page>
@{
    var watch = new Stopwatch();
    watch.Start();
}
<p>Total: @(Model.Descendants<Page>().Count())</p>
<ul>
    @foreach (var item in Model.Descendants<Page>())
    {
        <li>@item.Key - @item.Url()</li>
    }
</ul>
@{
    watch.Stop();
}
<p>Time elapsed: @watch.Elapsed</p>

I have also tested the following changes to the documentcache service which should be similar to your hacked code snippet with little to no effect on loading times for the crazy menu page

All of this is to say: I have found nothing that I think should be changed at this time as the system seems to behaving as expected. However I do agree that the performance difference is concerning and we should keep an eye on it. I will have further chats with the team/testing team about this to try and figure out if it is something we can change or if it is a performance penalty of the hybrid cache system.

Please do keep us informed if you find anything else, we really appreciate all the effort you have put into this and related reports #h5yr!

[enkelmedia]

Hi @Migaroez!

Thanks for looking at this!

The GC pressure that I managed to produce was mainly present when I load-tested the app, I was not looking at the startup performance, but at how it behaved under load.

The "runtime-cache-hack" does not really have any impact on startup but it did have a significant impact on page load times under load (since it avoids GC pressure). It kind of "patches" the fact that if a node is accessed multiple times during the same request it would re-create a new IPublishedContent constructed from the DTO in HybridCache each time it's accessed which should not be necessary.

IPublishedContent is more than a pure data object and it also holds data relative to the current execution context so it would be impossible to cache it across requests.

I get that this is the case and I kind of assumed that there is request/context-related information in IPublishedContent so any adjustments would not be a simple fix. I was thinking that maybe it would be possible to "re-hydrate" IPublishedContent with the context/request-specific information after fetching it from the cache to avoid having to re-create IPublishedContent objects on each load. This probably involves quite some work - but it would avoid a lot of allocations.

It's quite a dramatic difference in throughput that dropped by 62% in the test I made so it would be very nice to investigate if there is anything that can be done.

I will have further chats with the team/testing team about this to try and figure out if it is something we can change or if it is a performance penalty of the hybrid cache system.

Sounds great! 🚀

Let me know if there is anything that I can do to help!

[Migaroez]

I think it would give me an inclination of how bad things still are if you could run your tests again on the latest 16 RC Preferable on a dataset that does not have dead links (items in recycle bin or actually removed, as I am still looking into that one).

[enkelmedia]

Hi again @Migaroez!

I re-ran my tests on the latest code in main (v16.1-preview), on the same machine, same SQL Server instance and same database, this is the results:

Umbraco 13

RPS: 229
Median load time: 33ms
Startup to first render:

• (IgnoreLocalDb=true) 16.44s
• (IgnoreLocalDb=false) 11.35s

Umbraco 16.1-preview

RPS: 50
Median load time: 146ms
Startup to first render:

• 48.29s (seeding 100 items)
• 38.45s (seeding 50,000 items)

I did not have the time to recreate a new fresh db so there might still be some items in recycle bin and links to "dead" content in this db, but since sites are upgraded this scenario is far from unlikely.

There are quite some noticeable regressions here:

• Startup time is increased more than 3 times compared to "cold start" on v13, and more than 4 times compared to IgnoreLocalDb=false.
• RPS went from 229 to 50 (that's a more than 70% drop)
• Page load time is increased more than 3 times slower.

I revisited this and looked closer

Both the (old) nucache and the new hybridcache system use intermediate objects as IPublishedContent

When I tried to confirm this on v13, the ctor of PublishedContent is only hit during initial load, on subsequent page loads it's not hit and the fact that the IPublishedContent-instances keeps being re-created in v15/v16, both during the same request and on subsequent requests is the main problem here.

Looking at the ctor of e.g. PublishedContent it takes in the ContentNode-instance from the cache, IElementCache (singleton) and IVariationContextAccessor (singleton), it kind of feels like it would be possible to cache it in some way.

I did try to just "slam in" a cache that caches the IPublishedContent-instance in DocumentCacheService.GetNodeAsync() which made the test deliver 183 RPS, closer to v13 but not all the way.

From what I understand, the new HybridCache promised faster startup times but in this test case it's quite the opposite. I do get that there might be some 1% edge cases where a site with 100s of thousands of nodes loads faster, but I'm guessing that the vast majority of sites has less than 10k items, most sites does not have a Redis-cache (and should not need to either).

I think that these findings represents more than one issue and I also think that HybridCache might have limitations that makes these hard to get around.

In an ideal world it should be possible to:

• Seed the in memory cache in a more efficient way. Currently the SeedAsync()-implementation in DocumentCacheService just loops over the seed keys and fetches them from HybridCache on after the other, this is a lot less efficient than loading them all from the database in one go (or using paging as well).

• Cache the IPublishedContent-instance in memory and only use ContentCacheNode to serialize if a 2nd level cache is used. This is not supported with HybridCache (as far as I know) but could maybe be something to contribute and/or push Microsoft towards OR it HybridCache could be abstracted to allow different modes.

I can also see a alternative introduce an option where one could maybe opt-out of hybrid cache and just load everything into memory like in the "good old days" if they we want to. Personally I've always seen this as a good thing with Umbraco. Could maybe be different implementations of IDocumentCacheService depending on the needs of the implementing website.

I understand that this is probably a bigger commitment and not something that can be fixed with duct tape, but I do encourage you and the team to talk about this as there is a window for fixes with breaking changes now before V17.

As always, I'm more than happy to help out and let me know if you think I should be more concreate on any of the ideas.

All the best! 🚀

[ctolkien]

Just coming across this now as we're seeing significant performance issues in V15. We're seeing 50,000K SQL calls on first boot, which when combined with production stampeding means the site cannot boot.

[proxicode]

Also seeing very slow behavior in 15.3 & 15.4. In fact, the site becomes unusable slow if you work heavily in a list/collection node. For example, we are adding data for our client, they gave us a long list of past blog data. So, adding one after the other more than about 10 times slows the site down to a crawl. Checking resources reveals the browser is using gigs of memory so shut down the browser, start over, fine for a while then back to a crawl. Verified this across all major browsers and multiple machines. Occasionally get the "this site has stopped responding" browser error.
There is a fair amount of data, but nothing ridiculous. Like a 200 blog posts and less than 100 blog authors

[enkelmedia]

@proxicode Thanks for sharing your experience. I’m not sure if we are talking about the same issues. I’ve reported backend problems that would not surface in a browser.

Can you please explain more about your problem?

What kind of crawl are you talking about?

You mentioned that the “browser” used a lot of memory, are you referring to a browser used in the backoffice of Umbraco or the front end of your website?

It kind of sounds like you have a front end memory leak issue?

[enkelmedia]

Thanks @ctolkien! This is probably because you have a high number set for your seeding right?

One of the things I’m purposing is to be able to hydrate the memory cache in a “bulk”-fashion which would not be possible if a 2nd level cache is used - at the moment if feels like this is “by design” but I think that this needs to be revisited.

[RunarLoseth]

Hi, would just like to add to this issue that me and my team are experiencing similar issue with our upgrade build, moving from 13.7.1 (live) to 15.4.3 (test). The behaviour described here matches pretty well, we are seeing extensive first-load times of up to two minutes, and a huge increase in per-document load times after the fact.

Today's live environment has an expected load time of any document on the site of anywhere between 60 to 100ms.

Meanwhile in our test environment running 15.4.3, we are seeing numbers as high as 1600ms to load the exact same document, and as far as I've been able to test it more or less never drops below 1400ms. Document data is more or less exactly the same on both environments.

Static files if we do some cache busting drop from an average of 30ms to 200ms as well.

I haven't done any in-depth analysis of what could be causing the issue, so unfortunately I don't have much to add beyond what has already been said. As of right now we can't move our umb 15 build into production as the performance downgrade is way to high to be deemed acceptable for the end user so we are hoping to see a fix for this issue!