I'm having some performance problems with my Windows Azure Websites hosted Orchard instance. I'm running in Standard mode on a Medium instance.
I don't seem to be able to get initial page load time with output caching disabled under four seconds. Running MiniProfiler shows a top line item of my root page with a duration of over 4000ms; their doesn't appear to be any additional work going on. The additional
items are all trivial by comparison.
Any ideas on where to begin here? Running the site locally gives dramatically different results.
Jan 10, 2014 at 2:01 AM
Edited Jan 10, 2014 at 2:01 AM
For comparison, I configured a Medium instance VM in the West-US region, kept the database hosted in SQL Azure, and my page rendering time dropped to 33.8ms.
In both cases, I'm using a precompiled deployed (build.cmd Precompiled).
At a loss to explain this gap. I can't crank up logging on my Web Sites instance since it's in North Central US and storage accounts aren't available in that region right now, but I'm going to deploy to Azure Websites in the West region and do that next.
Anybody have any ideas?
Jan 12, 2014 at 12:59 PM
It's impossible to tell without more information what the problem could be. MiniProfiler should tell you roughly where the most time is spent.
Is your SQL DB in the same datacenter as your website?
Jan 12, 2014 at 10:00 PM
Edited Jan 12, 2014 at 10:01 PM
SQL DB is in the same data center as the web site. What's bizzare is just how little information MiniProfiler providers with regard to performance in this case.
On Azure Web Sites, requesting a page results in a timing for the Item/Display action with a top-level timing of 3500ms+ - i.e., it's spending 3.5 seconds just generating the markup. The subsequent action detail - views, etc. - are all 10-40ms each.
Edit - to be clear - this is the top item timing, 3500+ ms and 0ms from start, so this is the initial action.
Initially, I thought it was shenanigans associated with dynamic compilation, as discussed elsewhere, but I verified that my Web Sites deployment is precompiled with a configured HostComponents.config per elsewhere disabling dynamic compilation. The exact same
build deployed to a VM can generate page markup in a few hundred milliseconds.
Note that I'm trying as best as I can to compare apples-to-apples here, so my Websites instance is running in Standard mode, and I've made sure that my instance sizes are the same across deployment types.
Just so I'm clear on what I'm saying, here is the output of MiniProfiler:
duration (ms) from start (ms) query time (ms)
http://foobarbaz.com:80/ 4322.2 +0.0
Controller: Contents.ItemController.Display 2.6 +4314.5
Result: System.Web.Mvc.ViewResult 72.7 +4319.7
ApplyDriver 19.4 +4381.4
ApplyDriver 17.9 +4402.0
ApplyDriver 16.9 +4421.2
ApplyDriver 20.0 +4439.4
ApplyDriver 16.7 +4460.6
ApplyDriver 18.9 +4481.2
ApplyDriver 76.3 +4513.7 1 sql 60.3
EventBus: ISortCriterionProvider.Describe 17.2 +4514.1
EventBus: IMemberBindingProvider.GetMemberBin... 12.5 +4531.2
EventBus: IFilterProvider.Describe 18.5 +4544.1
EventBus: IMemberBindingProvider.GetMemberBin... 5.0 +4544.7
EventBus: ISortCriterionProvider.Describe 18.3 +4567.7
EventBus: IMemberBindingProvider.GetMemberBin... 7.8 +4585.8
Shape Display: Layout () (non-content) 4.6 +4687.4
As you can see, we're trying to figure out how to hand angle brackets to the web browser for more than four seconds in this case.
I'm open to ideas. Nothing like this behavior on a VM or a Web Role.
Jan 13, 2014 at 4:06 PM
Can you share the full Mini Profiler output (i.e. the one that can be clicked through)? You can also link to it.
I would share the link, but the client would rather I not. Oh well.
Here is the full output; not a lot more detail.
Item/Display (4817.3 ms) RD00155D4890FE on Mon, 13 Jan 2014 16:21:19 GMT
duration (ms) from start (ms) query time (ms)
http://foobarbaz.net:80/ 4223.1 +0.0
Controller: Contents.ItemController.Display 2.7 +4216.4
Result: System.Web.Mvc.ViewResult 69.5 +4221.6
Content Display: 103 () 4.1 +4279.5
ApplyDriver 17.8 +4279.8
ApplyDriver 16.1 +4302.3
ApplyDriver 21.7 +4319.7
ApplyDriver 19.5 +4342.9
ApplyDriver 19.1 +4363.7
ApplyDriver 19.4 +4384.1
ApplyDriver 71.4 +4417.2 1 sql 53.1
EventBus: ISortCriterionProvider.Describe 20.6 +4417.6
EventBus: IMemberBindingProvider.GetMemberBin... 9.1 +4438.0
EventBus: IFilterProvider.Describe 19.2 +4447.5
EventBus: IMemberBindingProvider.GetMemberBin... 5.2 +4448.1
EventBus: ISortCriterionProvider.Describe 20.7 +4472.0
EventBus: IMemberBindingProvider.GetMemberBin... 184.2 +4492.5
EventBus: IAuthorizationServiceEventHandler.A... 3.6 +4754.9
Shape Display: Parts_Contents_Publish (Detail... 3.7 +4781.9
show time with children 1.1 % in sql
from start (ms)
Dom Content Loaded Event 10.0 +165.0
Dom Complete +218.0
share show trivial
time from start
http://foobarbaz.net:80/ — 4216.60 ms
Slice GetContentItems <Display>b__1e <ContentShape>b__11 <ContentShapeImplementation>b__14 ApplyImplementation Apply <BuildDisplay>b__9 Invoke Invoke BuildDisplay BuildDisplay OnResultExecuting EndProcessRequest
DECLARE @p0 INT = 3;
SELECT DISTINCT TOP (@p0) contentite0_.Id AS col_0_0_
,integerfie3_.Value AS col_1_0_
FROM Orchard_Framework_ContentItemVersionRecord contentite0_
INNER JOIN Orchard_Framework_ContentItemRecord contentite1_ ON contentite0_.ContentItemRecord_id = contentite1_.Id
INNER JOIN Orchard_Projections_FieldIndexPartRecord fieldindex2_ ON contentite1_.Id = fieldindex2_.Id
INNER JOIN Orchard_Projections_IntegerFieldIndexRecord integerfie3_ ON fieldindex2_.Id = integerfie3_.FieldIndexPartRecord_id
INNER JOIN Orchard_Projections_IntegerFieldIndexRecord integerfie4_ ON fieldindex2_.Id = integerfie4_.FieldIndexPartRecord_id
WHERE integerfie3_.PropertyName = 'EventPart.StartDate.'
AND integerfie3_.Value >= 635252268840570248
AND integerfie4_.PropertyName = 'EventPart.EndDate.'
AND integerfie4_.Value >= 635252268840570248
AND integerfie3_.PropertyName = 'EventPart.StartDate.'
AND contentite0_.Published = 1
ORDER BY integerfie3_.Value
ApplyDriver — 13.60 ms
show trivial gaps