tags:

views:

259

answers:

3

I have an ASP.NET 2.0 web form that is taking almost 30 seconds to load. I am trying to figure out what is going on. I have enabled tracing and put in a whole bunch of Trace.Write statements so I can hopefully see what is going on. The results are very strange. They look like this...

aspx.page Begin Load 0.000245093984962406
MyEvent1 0.000446804511278195
MyEvent2 0.000464654135338346
MyEvent3 0.000477984962406015
aspx.page End Load 23.9897560037594

So all of the Trace statements that I put in (MyEvent1, MyEvent2, MyEvent3) fire very quickly. The last Trace statement that I put in is right at the end of the Page_Load event. So can anyone tell me what might be happening right after the final statement in the Page_Load event but before the End Load happens? I can't figure out what could be causing this to take so long. Is there some other way I can troubleshoot what is happening during the Page_Load event?

UPDATE - Adding code

     protected void Page_Load(object sender, EventArgs e)
     {
        Trace.Write("Starting Page Load");

        if (!Page.IsPostBack)
        {
            Trace.Write("Setting Body Tag and Meta Tags");
            HtmlGenericControl _mainBodyTag = (HtmlGenericControl)Page.FindControl("mainBodyTag");
            _mainBodyTag.Attributes["class"] = "drill membership";

            HtmlMeta _meta = new HtmlMeta();
            _meta.Name = "publication_date";
            _meta.Content = Sitecore.Context.Item.Statistics.Updated.ToShortDateString();
            Page.Header.Controls.Add(_meta);

            Trace.Write("Binding data");
            this.BindData();
        }
    }

    protected void BindData()
    { 
        //Feature
        Trace.Write("Setting Featured Item Info");
        litFeatureType.Text = "Report";
        hypTitle.Text = _feature.Fields["Title"].Value;
        hypTitle.NavigateUrl = LinkManager.GetItemUrl(_feature);
        hypReadMore.NavigateUrl = LinkManager.GetItemUrl(_feature);
        hypFeature.NavigateUrl = LinkManager.GetItemUrl(_feature);
        litFeatureText.Text = _feature.Fields["ShortDescription"].Value;
        litDate.Text = ((DateField)_feature.Fields["ReleaseDate"]).DateTime.ToShortDateString();
        litLocation.Visible = false;
        pnlMeeting.Visible = false;

        //News
        Trace.Write("Getting Member News");
        List<Item> _memberNews = _repository.GetMemberNews();
        rptNews.DataSource = _memberNews;
        rptNews.DataBind();

        //Lower Left
        Trace.Write("Getting lower left content");
        Item _home = Sitecore.Context.Database.SelectSingleItem("/sitecore/Content/Home");
        litLowerLeftContent.Text = _home.Fields["Lower Left Content"].Value;

        //Lower Right
        Trace.Write("Getting lower right content");
        litLowerRightContent.Text = _home.Fields["Lower Right Content"].Value;

        //Other Member Resources
        Trace.Write("Getting member resources items");
        Item _memberHome = Sitecore.Context.Database.SelectSingleItem("/sitecore/Content/Home/Member");
        rptMenu1.DataSource = _memberHome.Children;
        rptMenu1.DataBind();

        //Membership Stats
        Trace.Write("Getting membership stats");
        List<MembershipStat> _stats = _repository.GetMembershipStats();
        rptStats.DataSource = _stats;
        rptStats.DataBind();
        litTotal.Text = _totalCount.ToString();

        //Rail Content
        litRailContent.Text = _home.Fields["Right Rail Middle Content"].Value;

        Trace.Write("Finished");
    }

Updated - Adding trace output example:

Binding data    0.000103338345864662    0.000069
Setting Featured Item info  0.000174093984962406    0.000051
Getting Member News 0.000461293233082707    0.000287
Getting lower left content  0.0328178270676692  0.032357
Getting lower right content 0.0333527706766917  0.000535
Getting member resources items  0.0333826090225564  0.000030
Getting membership stats    0.130918973684211   0.097536
Finished    0.244487176691729   0.023386
aspx.page   End Load    23.9897560037594    23.745269
aspx.page   Begin LoadComplete  23.9898036541353    0.000048
aspx.page   End LoadComplete    23.9898190150376    0.000015
aspx.page   Begin PreRender 23.9898322293233    0.000013
aspx.page   End PreRender   23.9901133834586    0.000281
aspx.page   Begin PreRenderComplete 23.9901457819549    0.000032
aspx.page   End PreRenderComplete   23.9901602744361    0.000014
aspx.page   Begin SaveState 24.0240230714286    0.033863
aspx.page   End SaveState   24.0283510075188    0.004328
aspx.page   Begin SaveStateComplete 24.0283821616541    0.000031
aspx.page   End SaveStateComplete   24.0283963759398    0.000014
aspx.page   Begin Render    24.0284089849624    0.000013
aspx.page   End Render  24.0736610977444    0.045252
+1  A: 

Is there any reason you don't just set a breakpoint in page_load and trace through? That's a lot more useful then trace.write().

Update

If you really can't post code or debug using a normal debug server (like the one that is built in to Visual Studio), then try commenting out all of the code in page_load and see how long it takes.

Update Update Try reducing the amount of data being bound and see if that solves your problem (or at least points you in the right direction).

From your example:

List<Item> _memberNews = _repository.GetMemberNews();
rptNews.DataSource = _memberNews;
rptNews.DataBind();

change to this

List<Item> _memberNews = _repository.GetMemberNews();
_memberNews = _memberNws.GetRange(0,10);
rptNews.DataSource = _memberNews;
rptNews.DataBind();

Thus reducing the number of rows for this control to 10. Do this for each of your databound controls to fix the amount of data being processed in your render event. At the very least it will give you an idea of where the bottleneck is.

David Lively
I can't add a breakpoint because it is on a production server so I can't step through the code. And there is really no code to post. What I am trying to say is that all of the code that runs in the Page_Load event in the code behind for the file seems to run very quickly. The Trace statements seem to show that there is nothing in there that is causing the slowness. But then after everything has executed in the Page_Load event, it then takes another 23 seconds for the End Load to show up in the Trace output. That's what I'm trying to figure out.
Corey Burnett
If there is any code in the page_load event, then there is code to post. Also, why not debug this on your local server? You're not really doing all of your testing on a production server, are you?
David Lively
You really want me to post 200 lines of code that basically access a CMS system and a few stored procedures and set control values on a page? What I'm trying to say is that all 200 lines of my code execute quite quickly. (at least according to Trace output) But then for some reason it takes about 23 seconds from when the last line in my Page_Load event fires before the End Load shows up in the Trace output. I am hoping that someone can help me understand what is happening there - what is ASP.NET doing? Also, it runs fine in development, that is why I am tracing in production.
Corey Burnett
If you won't try some basic debugging techniques, there's not a lot we can do to help you.
David Lively
What are the basic debugging techniques that I won't try?
Corey Burnett
*sigh*. Comment out the freakin' page_load() code, as I suggested above. I don't really care if you fix it, but when in doubt, remove the offending component and verify that the problem disappears. If not, your issue is somewhere else.
David Lively
Sorry to bother you so much.
Corey Burnett
I think you are missing the point of my question. I am not asking what is wrong in my code. I am asking if anyone know what happens in the ASP.NET page life cycle after the code that is in Page_Load is finished. From looking at the trace output it would seem that something is taking 23 seconds *after* the code in Page_Load is finished, but before End Load shows up in the trace output.
Corey Burnett
Does your test environment have the same data (and quantity of data) as what is being used in production? Also, LOTS of things happen after page_load(). See http://msdn.microsoft.com/en-us/library/ms178472.aspxRender is going to take the most time as you're DataBinding a lot of stuff. This is fine, but it can generate a lot of work depending on db speed, query efficiency, etc.
David Lively
No, that's probably part of the problem. My test environment does not have the exact same data or quantity of data or load on it. I know that there are a lot more advanced things that I can do to try and solve this - remote debugging, load testing in development, etc. At some point I may have to go down that road. For now I am trying to find out if there is anything else that is simpler that I can do. The answer may be no - and that is fine. But I wanted to try the easiest things first.
Corey Burnett
I'd suspect the number of rows of data being processed by each databind(). This can eat serious time. See my post update for a suggestion.
David Lively
Yes, I know that there are lots of things that happen after page_load. But from looking at the trace output on my page it would seem that rendering is taking almost no time at all. Begin Render and End Render happen very, very quickly. The 23 second delay is in the Load event but it occurs *after* all of my code has run.
Corey Burnett
It's probably in the data binding, then.
David Lively
Ok. But if I have trace.write statements that occur *after* the databinding statements doesn't that mean that the databinding has finished? All of my trace.write statements are finished very quickly. And then after the one that says "Finished", there is a 23 second delay until the End Load line shows up in the trace output.
Corey Burnett
I could be wrong, but I don't think emission of the data happens until Render.
David Lively
Hmmm...so even though my DataBind() line of code doesn't take very long to run, the actual binding of the data doesn't happen until Render? I have also added the actual output from the trace so that you can see what I am talking about. You can see that Render doesn't take very long at all.
Corey Burnett
Also - I looked at the data bindings that I am doing and they all have between 4 and 10 items. So it's not like there is a huge amount of data.
Corey Burnett
+1  A: 

If possible, consider attaching a remote debug session to your production server. You should then be able to set breakpoints, etc, and see what, exactly, is going on.

Steve Elmer
That will stop the server from processing requests though.
David
+1  A: 

Are you using a master page? Any user controls or custom server controls on the page? If so, you may want to investigate the Page_Load in those controls.

Paulus E Kurniawan
It turned out that there were other custom server controls on this page that I was unaware of. I found the offending code in those controls.
Corey Burnett