Timeout on Many Content Items

Topics: Core, Customizing Orchard, Troubleshooting
Oct 18, 2011 at 4:05 AM

Hi,

We were just trying to test the performance of Orchard, and tried inserting around 180,000 content items into one tenant.

Now, after doing this, we are getting timeout even on listing the content items in admin panel.

Is it a bug? Or we have done something wrong? It look as Orchard is trying to join more than 4-5 tables for listing the data, we are using Orchard 1.2 and I was wondering if this case has been solved in 1.3?

Thanks in advance.

Oct 18, 2011 at 9:03 AM

Orchard will always join multiple tables to load a content item; this is an aspect of the modular architecture, allowing each part to store data in a separate table. In and of itself it shouldn't cause any performance issues (the tables are 1-1 joins, and it's way better than the alternative of a separate database request for each part, or a single huge table which will have a load of redundant fields for any given content item).

However, there are other issues that are being worked on. Orchard 1.3 introduces some optimisations for multi tenant scenarios, which could certainly help your situation. One problem could be that the Routable map is held in memory; in your case, resulting an in-memory dictionary with 180,000 entries.

Of course it also depends exactly what modules you're using. Listing items in the admin panel should be a limited query (i.e. 20 items or so) so it's somewhat surprising you'd get timeouts there (with only core modules at least).

There's a Performance team being formed for work on future Orchard so you might want to weigh in with your findings: http://orchard.codeplex.com/discussions/274921

Coordinator
Oct 18, 2011 at 5:54 PM

Are you saying that the site is not responsive during the import or even after ?

Oct 18, 2011 at 6:52 PM

Content List doesn't work after importing, it gives me timeout after importing data.

Any suggestion?

Coordinator
Oct 18, 2011 at 7:15 PM

Based on the source code the list should be paged and should work just fine, but I will try to get a lot of content and look at the sql query. I'll post as I have more information.

Coordinator
Oct 18, 2011 at 7:32 PM

I don't see anything weird here. What is the list of content types you have created, and which parts are attached to it. Any other module that could trigger it ?

Oct 19, 2011 at 8:02 AM

All content items we have created are in one list (which might be the problem too), and also the following aprts are attached, I guess by putting them in different lists and making them archived, we can have a better performance, is that right?

Body
Comments
Common
Containable
Menu
Menu Relation
Route
Tags
Custom Properties
Admin Menu
Image Gallery
Pulish Later
Container

Oct 19, 2011 at 2:09 PM

I'm wondering if the Menu Relation and/or Image Gallery parts could be having an impact, since they're from third party modules. Relationship hierarchies in particular can cause exponential performance problems (which is why I'm looking at Menu Relation - which module is that from?) In my Mechanics module I started to see serious performance issues when creating multiple-level menu hierarchies, since for each content item that was loaded I was then loading all its related items. I've patched this up by hiding relationships in the admin screens, and with caching in the front-end - but that module might not be doing so.

If you run the test again but just with Core parts, do you see the same issues?

Jan 19, 2012 at 8:57 AM

This is very interesting because i have basically the same setup and my back-end as well as my front-end is really became very slow. I have also installed the Image Gallery and Advanced menu modules. I have "just" around 10.000 items. I'm using V1.3 so any suggestions how i can make things faster for this version and these two modules. I strongly suspect the combination of these modules and amount of content items of the bad performance.

Jan 19, 2012 at 9:18 AM

Have you tried the MvcMiniProfiler module to see where bottlenecks might be?

I made a fork which has more detailed output than the default: http://orchardprofiler.codeplex.com/SourceControl/network/Forks/randompete/downplayorchardprofiler

Jan 19, 2012 at 2:43 PM

Yes i tried you fork but unfortunately i can't find the bottlenecks. I do see the following taking much time:

Shape Display: FootScripts () (non-content) 571.8 +7080.2
Shape Display: HeadScripts () (non-content) 251.0 +6821.8

I this known? of am i looking in the wrong direction? thanks!

 

Jan 19, 2012 at 3:11 PM

It's pretty strange that those methods are taking so much time. One possibility is if some part of a content handler or view is somehow requiring or including a script, so it's creating 10,000 lookups in the Scripts system. Maybe you could debug through the Script generation code to check what's going on.

Another possibility is that the bottleneck isn't actually there, but in a process that runs around the same time. The problem with the Profiler is that, due to the often slightly obfuscated flow of control in Orchard, the profiler doesn't always represent the whole truth, it can only go on what it has been told is happening, and sometimes code is executing outside of the current profiler scope.

An example: a ContentHandler sets a Lazy Loader on a Part, and that lazy loader is performing a complex content query. So that query eventually gets performed in a completely irrelevant-seeming location when that property just happens to be accessed. It's completely non-obvious that it's a delegate that actually came from elsewhere causing the bottleneck.

I started copying more Orchard core dependencies into Profiler and adding profiling calls to get a more complete picture. But I was ending up with so much duplicated code that of course would need manually updating each time the core dependencies change that I ditched that plan and decided on a different strategy. My plan is to fork Orchard itself to create a Profiling-targetted version, so profiling commands can be added in a lot of needed places in core, and future updates can simply be merged in. I didn't get around to this yet though, I have some features to finish before I get down to some serious optimisation for my own sites :)

A big change currently needed in Profiler is allowing it to show where the SQL queries are coming from. It does a very nice job of listing all the SQL queries and how long they take; but it gives absolutely no clue as to where and when the queries were generated!

To help with this: can you paste in the entire output of the profiler (from the "Share" link), and also tell it to show trivial data as well, because it's actually quite important to see how methods were arrived at. I'd just like to see if I can offer an alternative interpretation of the results, they can be somewhat confusing. Also have a scan through the SQL queries and see if anything is taking a particularly long time there.

Jan 19, 2012 at 3:21 PM

Additional note: I took a look through ResourceManager.cs. It seems to me that there is a situation where if 10,000 Requires were added, even if they were all for the same resource, the execution of the FootScripts and HeadScripts shapes could indeed become very slow. There might be a fairly simple optimisation to apply there (preventing requires from being listed multiple times in the first place!) Or alternately you could try and narrow down how and where the Require is happening and fix it at the source, which would be preferable if it's possible. Assuming it emerges that scripts are indeed the problem, of course!

Jan 19, 2012 at 3:34 PM
Edited Jan 19, 2012 at 3:39 PM

Thanks for your support. I found the main problem! After some disabling of modules and further testing i came to the conclusion that following code of ImageGalleryService of the module Mello ImageGallery was the main problem:

if (!_mediaService.GetMediaFolders(string.Empty).Any(o => o.Name == ImageGalleriesMediaFolder))
{
  _mediaService.CreateFolder(string.Empty, ImageGalleriesMediaFolder);
 }

this code cost me around 6/7 second per page view!! amazing. Can somebody explain why? I do have a lot of image folders. is the I/O the main problem here?

Jan 19, 2012 at 3:50 PM

Disk I/O is always inherently slow (and additionally creates locking problems under heavy load), which is why things are optimised by being in the DB or even in memory cache.  Since that code is enumerating all the media folders it will be slowed down if you have a lot. I wonder is there a further problem whereby that code is getting called 10,000 times for a page load? Did you try breakpointing it to see how often it was called? It shouldn't take that long ... although I guess enumerating 10,000 folders could have an impact on its own :)

Jan 19, 2012 at 5:07 PM

yes indeed. I really have around 10.000 media sub folders. The main problem is that this code was executing in the driver constructor. so even when this module wasn't used on the page, this module still had to executed that slow code. This problem has cost me a lot of time so hopefully i can help others steer in the right direction by this topic when they have similar problems!

Jan 19, 2012 at 5:25 PM
Edited Jan 19, 2012 at 5:27 PM

Ouch! That's why I always recommend the following to avoid major performance implications:

a) Never perform any work in a constructor. All that should ever be happening is storing dependency references, and sometimes creating delegate functions (e.g. in ContentHandlers). On a single page request, nearly every dependency in every module gets instanced due to the dependency graph being what it is. In this particular case, he could have created a lazy loader to grab that data when required.

b) In drivers there's an additional concern. Ideally you don't want to perform any work outside of the factory delegate in your shape result, i.e.:

 

        protected override DriverResult Display(MyPart part, string displayType, dynamic shapeHelper) {
            // This is bad:
            var data = PerformWork();

            return ContentShape("Parts_MyPart", () => shapeHelper.Parts_MyPart(Data: data));
        }

        protected override DriverResult Display(MyPart part, string displayType, dynamic shapeHelper) {
            // This is far, far better:
               return ContentShape("Parts_MyPart",
                   () => {
                         var data = PerformWork();
                         return shapeHelper.Parts_MyPart(Data: data));
                  });
        }

The reason for this being that in the second case, if your part is hidden due to Placement, then the delegate won't run and the work won't be performed. In the first case, the work is performed every time regardless, even if e.g. you're rendering a summary list of 100 items where the part isn't required!

 

BTW - I realise it wasn't your code at fault, but these two points are so important they're worth repeating again and again :)

Jan 19, 2012 at 6:34 PM

@thanks randompete for you great advise! To many modules are doing this wrong.

Jan 20, 2012 at 8:39 AM

update: by profiling i saw that the require scripts and require styles took to long. When i remove theses require statements from my theme layout.cshtml the load time of my pages is 50% less then with them. So an amazing performance boost! The only problem is that i need all those scripts and styles which are being included. Somebody an idea how i can optimize this but still use those scripts and styles?

Coordinator
Jan 20, 2012 at 8:41 AM

Weird. Would you share those profiles?

Jan 20, 2012 at 10:19 AM
Edited Jan 20, 2012 at 10:33 AM

ok i've found some interesting things. I fixed the following problems and my pages is amazing fast!

  1. I had two modules which both have a ResourceManifest and both had the same scripts with the same require name but different js. Ofcourse this resulted in problems. I strongly suspect this problem to be the performance bottleneck.
  2. Two many script and style require's in my theme layout. I moved a lot to the right module part views/cshtml's.

Unfortunately i don't have the time at the moment to fully inspect the problem. Maybe next week i'll try to reproduce this.

thanks!

Jan 20, 2012 at 1:59 PM

Great you got it solved, and the profiler took you quickly there. It can still be improved a lot. I think having a dedicated profiling module can prove to be very powerful compared to external tools, because it understands Orchard's internals. I found the results of external (commercial) profilers very hard to interpret, when they worked at all ;)  It's just a shame Four2n don't accept my pull requests... :(

Jan 20, 2012 at 4:09 PM
Edited Jan 20, 2012 at 4:10 PM

yes your fork is really great and saved me a ton of time! once again great work! That's indeed a good idea!

I do had to upgrade the mini profiler dll because i run into the json limit. They have a patch to make sure you can use the max json size instead of the default.

Jan 20, 2012 at 4:28 PM
Edited Jan 20, 2012 at 4:28 PM

I'll update to the new dll as well (I don't think there's a way to make pull requests between forks). When I fork Orchard for a profiling version it'll automatically include my fork as the profiling subrepo.

Actually I might end up with a separate Profiler module anyway. I'd started writing one before I found the MvcMiniProfiler project. It's a nice project but there are certain things I find a bit inflexible. The output could be clearer, and the little overlay thing obscures my menu in the top-left! Simple things like a Javascript expand/collapse tree would be nice, and I'd like to do some aggregation over the final results (so e.g. you could aggregate the total time spent in a particular method, if that method is called many times throughout a request, which would be more meaningful for instance in cases of events that are frequently called).

Coordinator
Jan 20, 2012 at 5:54 PM

Maybe forking the project and releasing it on the gallery would be the solution. Other solution: integrate in ShapeTracing.

Jan 20, 2012 at 6:09 PM

It already integrates into shape events but that doesn't give a full picture of everything (e.g. the driver responsible runs before the shape is created and way before it's actually rendered, so you get skewed data; I want to see which drivers need optimising, or where heavy content queries are coming from).

So to get a really complete picture I need to add profiling hooks all over the place - in all the core Orchard services (IContentManager, IContentDisplay, part and field driver coordinators, event bus, content query, and many others). The built-in extension points just aren't in the right places to capture accurate data. A separate fork of Orchard just seems the right way to go with this. When you see the results you'll be convinced :)

Coordinator
Feb 10, 2012 at 7:38 AM

I can confirm that moving the problematic image gallery constructor code out and making it do its work lazily only when needed improves perf greatly. I may post a fork sometime.

Jun 4, 2012 at 6:19 PM
Edited Jun 4, 2012 at 6:33 PM

- edit