Orchard 1.8 Slow SQL Performance

Topics: Administration, Customizing Orchard, Troubleshooting
Aug 26, 2014 at 3:36 PM
Edited Aug 26, 2014 at 3:44 PM
I have deployed an Orchard 1.8 in my production server. The production server is a dedicated server with extremely good specs. Yet the loading time of EACH page is around 3 to 4 seconds which is very slow in our standard. We have over ONE MILLION Content Items and we were under the impression that Orchard is capable of handling such load. Even loading the empty homepage takes that amount of time. So I installed the MiniProfiler module and managed to pinpoint the bottleneck. It is from this SQL query
DECLARE @p0 NVARCHAR(4000) = N'Layer'
        ,@p1 BIT = 1;

SELECT this_.Id AS Id1795_2_
        ,this_.Number AS Number1795_2_
        ,this_.Published AS Published1795_2_
        ,this_.Latest AS Latest1795_2_
        ,this_.Data AS Data1795_2_
        ,this_.ContentItemRecord_id AS ContentI6_1795_2_
        ,contentite1_.Id AS Id1794_0_
        ,contentite1_.Data AS Data1794_0_
        ,contentite1_.ContentType_id AS ContentT3_1794_0_
        ,contenttyp2_.Id AS Id1796_1_
        ,contenttyp2_.NAME AS Name1796_1_
FROM Orchard_Framework_ContentItemVersionRecord this_
INNER JOIN Orchard_Framework_ContentItemRecord contentite1_ ON this_.ContentItemRecord_id = contentite1_.Id
INNER JOIN Orchard_Framework_ContentTypeRecord contenttyp2_ ON contentite1_.ContentType_id = contenttyp2_.Id
WHERE contenttyp2_.NAME = @p0
        AND this_.Published = @p1
I have added indexes for table Orchard_Framework_ContentTypeRecord (Name column ASC) and table Orchard_Framework_ContentItemVersionRecord (Published column DESC), but doesn't improve the script execution time.

How do I relieve this bottleneck? This is really a deal breaker, we have spent several months customizing this site for a client which require us to pump in ONE MILLION content items. We're on the verge of scraping the whole project away if this situation can't be remedied. Please help.
Coordinator
Aug 26, 2014 at 6:20 PM
Have you tried 1.8.1 ?
The content type should not be queried directly here, but by Id, this is an optimization I did for 1.8 or 1.8.1 (can't remember exactly) which allowed us to test the system with several millions of content items. This work was triggered by another customer who is also using 10s of millions of content items.

If you could confirm you are on 1.8.1 then I will check why the query is like this.

How many widgets and layers do you have?
Aug 26, 2014 at 6:43 PM
sebastienros wrote:
Have you tried 1.8.1 ?
The content type should not be queried directly here, but by Id, this is an optimization I did for 1.8 or 1.8.1 (can't remember exactly) which allowed us to test the system with several millions of content items. This work was triggered by another customer who is also using 10s of millions of content items.

If you could confirm you are on 1.8.1 then I will check why the query is like this.

How many widgets and layers do you have?
Thanks for your reply.
I have 11 widgets and 12 layers in total.

I'm on v1.8.0, I will try and update to v1.8.1 first to see if it helps solve the problem. Will keep you updated
Aug 26, 2014 at 9:33 PM
I've upgraded to v1.8.1 and the SQL statements executed at the bottleneck is exactly the same. However I am not sure if that is the problem.

I did a test by deploying new instances of Orchard 1.8.1 on both my production server and my development machine. Then pumped both instances with exactly the same one million content items. Next I executed the SQL script above using SQL Server Management Studio on both server and development machine. My production server took more than 2 seconds to retrieve the results while my development machine took less than a second to retrieve the exact same results.

This is weird because my production server is much more powerful than my development machine. The server is a dedicated lean machine running only that Orchard instance, while my development machine besides running the Orchard instance, also has Visual Studio 2013 opened together with 20++ browser tabs. My server has 16GB of RAM while my development machine only has 6GB and the memory usage is at 96% high. The server is running Windows Server 2012 with SQL Server 2014 Entreprise Edition while my development machine is running Windows 7 with SQL Server 2012 Express Edition. The SQL statements Execution Plans for both machines are different too. I'm not really proficient at reading execution plans but I can include the xml version execution plan here if it's necessary.

What gives?
Coordinator
Aug 28, 2014 at 1:59 AM
I have checked the code and the improvement has been applied in 1.x. You should try it to see if it solves your issue, then you'd have two options: swith to 1.x, or backport the change (which should be pretty simple as it target only one class AFAIK)
Aug 28, 2014 at 10:32 AM
You should check the installation of your SQL Server 2014 Entreprise Edition, such a diff between dev station and prod is not normal, should be the inverse.
I am not sure that SQL Entreprise is needed if only Orchard is running on it. Entreprise version has complex log features which could slow down thing when securing them.
May be do a try with an SQL 2012 Enterprise or Web version.
Coordinator
Aug 28, 2014 at 5:57 PM
First simple I'd look at is the Power options. They are on power economy by default which slows everything CPU bound. And use 1.x ;)
Aug 29, 2014 at 1:05 AM
Finally, I'm able to pinpoint that the problem lies with SQL Server. When it comes to execute the above script, SQL Server 2014 query optimizer generated a less than optimal execution plan compare to SQL Server 2012. So my strategy now is to force SQL Server 2014 (production server) to use the execution plan of SQL Server 2012 (development machine).

This is really a problem with SQL Server and not Orchard but since I've already created this question, I might as well share my attempts. I query the above script in an ad hoc fashion in SQL Server 2014 using the execution plan from SQL Server 2012.
DECLARE @p0 NVARCHAR(4000) = N'Layer'
        ,@p1 BIT = 1;

SELECT this_.Id AS Id1795_2_
        ,this_.Number AS Number1795_2_
        ,this_.Published AS Published1795_2_
        ,this_.Latest AS Latest1795_2_
        ,this_.Data AS Data1795_2_
        ,this_.ContentItemRecord_id AS ContentI6_1795_2_
        ,contentite1_.Id AS Id1794_0_
        ,contentite1_.Data AS Data1794_0_
        ,contentite1_.ContentType_id AS ContentT3_1794_0_
        ,contenttyp2_.Id AS Id1796_1_
        ,contenttyp2_.NAME AS Name1796_1_
FROM Orchard_Framework_ContentItemVersionRecord this_
INNER JOIN Orchard_Framework_ContentItemRecord contentite1_ ON this_.ContentItemRecord_id = contentite1_.Id
INNER JOIN Orchard_Framework_ContentTypeRecord contenttyp2_ ON contentite1_.ContentType_id = contenttyp2_.Id
WHERE contenttyp2_.NAME = @p0
        AND this_.Published = @p1
OPTION (USE PLAN N'<ShowPlanXML ..... (Execution Plan here)')
The query took less than a second to execute which is the desired result. Now, I can't put this execution plan in Orchard core source codes, can I? So I have to create a Plan Guide in SQL Server 2014 and include this Execution Plan. This is what I did
EXEC sp_create_plan_guide 
@name = N'Published_Layer_Content_Type',
@stmt = N'SELECT this_.Id AS Id1795_2_
        ,this_.Number AS Number1795_2_
        ,this_.Published AS Published1795_2_
        ,this_.Latest AS Latest1795_2_
        ,this_.Data AS Data1795_2_
        ,this_.ContentItemRecord_id AS ContentI6_1795_2_
        ,contentite1_.Id AS Id1794_0_
        ,contentite1_.Data AS Data1794_0_
        ,contentite1_.ContentType_id AS ContentT3_1794_0_
        ,contenttyp2_.Id AS Id1796_1_
        ,contenttyp2_.NAME AS Name1796_1_
FROM Orchard_Framework_ContentItemVersionRecord this_
INNER JOIN Orchard_Framework_ContentItemRecord contentite1_ ON this_.ContentItemRecord_id = contentite1_.Id
INNER JOIN Orchard_Framework_ContentTypeRecord contenttyp2_ ON contentite1_.ContentType_id = contenttyp2_.Id
WHERE contenttyp2_.NAME = @p0
        AND this_.Published = @p1',
@type = N'SQL',
@module_or_batch = NULL,
@params = N'@p0 NVARCHAR(4000), @p1 BIT',
@hints = N'OPTION (USE PLAN N''[Execution Plan here. All single quotes are escaped accordingly]'')'
The Plan Guide is created successfully. I've verified that using SELECT * FROM sys.plan_guides. However, whenever I execute the query, the Execution Plan wasn't used. What gone wrong? Did I created the Plan Guide wrongly?
Coordinator
Aug 29, 2014 at 1:08 AM
can you try to apply the fix I did this morning under the changeset af0ea26f85922acbb476f1197eec937118904277

This might force to a better query plan as it will join with the LayerPartRecord and thus limit the scan on the content item table. The changes are very simple.
Aug 29, 2014 at 4:50 AM
Edited Aug 29, 2014 at 4:53 AM
sebastienros wrote:
can you try to apply the fix I did this morning under the changeset af0ea26f85922acbb476f1197eec937118904277

This might force to a better query plan as it will join with the LayerPartRecord and thus limit the scan on the content item table. The changes are very simple.
I have applied the changes and rebuilt the two Orchard projects in Release mode.
It is still executing the exact same SQL Statement using the same amount of time. Nothing changes. =(
Apr 27, 2015 at 10:02 PM
I am also having serious performance issues with Orchard.
I beleive I have followed all the recommendations for improving performace. Basically, for each page, there is a 2.5s (or more) delay between when the request is made, and Orchard starts to deliver the content. I have very similar results on both versions 1.7.2 and 1.8.1. The first page load times are worse - around 4s for if the cache is expired.

In attemt to speed-up, I have migrated the database to SQL Srever 2012 (from local Express) - with no appreciable increase in performance. However, it did give me an opprotunity to analyse the SQL Queries behind the scenes.

Conclusion is the Menu widget has poor perfomance for a large number of menu items.

Details below:

Looking at an SQL trace, I can see two disticnt phases befor the page content is delivered:

Stage 1: about 210 queries generally, grouped set like the set below (note the common @pXXX=374 in the queries)
declare @p1 int
set @p1=9123
exec sp_prepexec @p1 output,N'@p0 int,@p1 bit',N'SELECT this_.Id as Id1301_2_, this_.Number as Number1301_2_, this_.Published as Published1301_2_, this_.Latest as Latest1301_2_, this_.Data as Data1301_2_, this_.ContentItemRecord_id as ContentI6_1301_2_, contentite1_.Id as Id1300_0_, contentite1_.Data as Data1300_0_, contentite1_.ContentType_id as ContentT3_1300_0_, contenttyp4_.Id as Id1302_1_, contenttyp4_.Name as Name1302_1_ FROM Orchard_Framework_ContentItemVersionRecord this_ inner join Orchard_Framework_ContentItemRecord contentite1_ on this_.ContentItemRecord_id=contentite1_.Id left outer join Orchard_Framework_ContentTypeRecord contenttyp4_ on contentite1_.ContentType_id=contenttyp4_.Id WHERE contentite1_.Id = @p0 and this_.Published = @p1',@p0=374,@p1=1
select @p1
go
declare @p1 int
set @p1=9124
exec sp_prepexec @p1 output,N'@p0 int',N'SELECT contentite0_.Id as Id1300_0_, contentite0_.Data as Data1300_0_, contentite0_.ContentType_id as ContentT3_1300_0_ FROM Orchard_Framework_ContentItemRecord contentite0_ WHERE contentite0_.Id=@p0',@p0=374
select @p1
go
declare @p1 int
set @p1=9125
exec sp_prepexec @p1 output,N'@p0 int',N'SELECT versions0_.ContentItemRecord_id as ContentI6_1_, versions0_.Id as Id1_, versions0_.Id as Id1301_0_, versions0_.Number as Number1301_0_, versions0_.Published as Published1301_0_, versions0_.Latest as Latest1301_0_, versions0_.Data as Data1301_0_, versions0_.ContentItemRecord_id as ContentI6_1301_0_ FROM Orchard_Framework_ContentItemVersionRecord versions0_ WHERE versions0_.ContentItemRecord_id=@p0',@p0=374
select @p1
go
declare @p1 int
set @p1=9126
exec sp_prepexec @p1 output,N'@p0 int',N'select contentite0_.Id as Id1301_, contentite0_.Number as Number1301_, contentite0_.Published as Published1301_, contentite0_.Latest as Latest1301_, contentite0_.Data as Data1301_, contentite0_.ContentItemRecord_id as ContentI6_1301_ from Orchard_Framework_ContentItemVersionRecord contentite0_ where contentite0_.ContentItemRecord_id=@p0 and contentite0_.Published=1',@p0=374
select @p1
go
The complete set of queries here take 2.3 seconds between the first and last query. This where the performance is being killed.

Following this, there ar a large number of smaller queries, but all identical in all but the parameter value, and these complete much more quickly. In all there are about 310 individual queries all like:
declare @p1 int
set @p1=9513
exec sp_prepexec @p1 output,N'@p0 int',N'SELECT commonpart0_.Id as Id1306_0_, commonpart0_.OwnerId as OwnerId1306_0_, commonpart0_.CreatedUtc as CreatedUtc1306_0_, commonpart0_.PublishedUtc as Publishe4_1306_0_, commonpart0_.ModifiedUtc as Modified5_1306_0_, commonpart0_.Container_id as Container6_1306_0_ FROM Common_CommonPartRecord commonpart0_ WHERE commonpart0_.Id=@p0',@p0=690
select @p1
These identical 310 queries execute and are processed in about 200ms - my guess as an effective use of a prepared single SQL statement.

The site in question is not particularly complex - but does contain 220 menu (mostly consisting of Content Menu Item links). I suspected that the relatively large number of menu items is behind the large number of queries was behind this. So, in a test environment, I deleted all but 8 of the menu items, and opened the same home page (unaltered except for the detail in the menu), and the intial response has changed from 2500ms down to 172ms.

What is a little unusual is the fact that the menu if built as a single monolithic menu, where in one widget I display only the top level menu, and the another widget, I display the remaining menu levels as a cascade.

In my experience, the Menu widget is seriously flawed from a performance point of view. It might be worth seeing if other having problems with performance also see drmaitic improments if the menu widget is greatly trimmed down.

I'll update on any developments.
Developer
Apr 27, 2015 at 11:33 PM
This is a known issue with the Menu widget - the more items it has, the longer it takes to load and render. You could consider using output caching (at the page level or widget level) varied by URL. Not a true fix, but at least your site will perform significantly better until a real fix comes along.

Note to self: Perhaps we could load all menu items in one go instead of loading them individually (if that's actually happening). Also see what the impact is of having each menu item rendered as its own shape vs a single menu shape template that renders the menu. Would be less flexible, but perhaps that would be OK for most cases.
Developer
Apr 28, 2015 at 5:27 AM
The menu is loading everything with one query if you only use Custom Links. My guess is that you use Content Menu Items that will issue multiple queries for each of the menu items when loading the content item in the background. The workaround is to only use Custom Links.