12 seconds from accessing database.config file to processing

[jpopowski1]

Still trying to figure out why our site is so slow running AC. Using filemon.exe you can see that the delay from the time the system reads the database.config file to working on the graphics is 12 seconds.

2 3:13:18 PM w3wp.exe:3908 QUERY INFORMATION D:\WEB.ROOT\greendesic\web.config SUCCESS Attributes: A
133 3:13:18 PM w3wp.exe:3908 QUERY INFORMATION D:\WEB.ROOT\greendesic\App_Data\database.config SUCCESS Attributes: A
134 3:13:18 PM w3wp.exe:3908 QUERY INFORMATION D:\WEB.ROOT\greendesic\web.config SUCCESS Attributes: A
135 3:13:18 PM w3wp.exe:3908 QUERY INFORMATION D:\WEB.ROOT\greendesic\App_Data\database.config SUCCESS Attributes: A
136 3:13:30 PM explorer.exe:2160 OPEN C:\ SUCCESS Options: Open Directory Access: 00100000
137 3:13:30 PM explorer.exe:2160 QUERY INFORMATION C:\ SUCCESS FileFsFullSizeInformation
138 3:13:30 PM explorer.exe:2160 CLOSE C:\ SUCCESS
139 3:13:30 PM explorer.exe:2160 OPEN D:\ SUCCESS Options: Open Directory Access: 00100000
140 3:13:30 PM explorer.exe:2160 QUERY INFORMATION D:\ SUCCESS FileFsFullSizeInformation
141 3:13:30 PM explorer.exe:2160 CLOSE D:\ SUCCESS
142 3:13:32 PM w3wp.exe:3908 OPEN D:\WEB.ROOT\greendesic\Assets\gisProductImages\cleopaj_search.jpg SUCCESS Options: Open Access: Read
143 3:13:32 PM w3wp.exe:3908 QUERY INFORMATION D:\WEB.ROOT\greendesic\Assets\gisProductImages\cleopaj_search.jpg SUCCESS Length: 2469
144 3:13:32 PM w3wp.exe:3908 READ D:\WEB.ROOT\greendesic\Assets\gisProductImages\cleopaj_search.jpg SUCCESS Offset: 0 Length: 8192
145 3:13:32 PM w3wp.exe:3908 CLOSE D:\WEB.ROOT\greendesic\Assets\gisProductImages\cleopaj_search.jpg SUCCESS
146 3:13:32 PM w3wp.exe:3908 OPEN D:\WEB.ROOT\greendesic\Assets\gisProductImages\fullrobe_search.jpg SUCCESS Options: Open Access: Read

What could be causing this delay?

[AbleMods]

Is the site idle alot? If so, then that sort of delay is expected. IIS will only cache the compiled .Net code for so long. After that, it tosses it until the next web hit. Then it fires a full recompile of the whole site.

My sites take 8-12 seconds to load after an IIS restart. After that, it's 2-4 seconds for full page view.

There are some free keep-alive utilities out there that will ping your site every so often to keep IIS from tossing the compiled version from memory due to inactivity.

[jpopowski1]

This happens when I'm on the site, have just gone to several pages, and then choose one particular category of products that has quite a few entries.

[AbleMods]

Define "quite a few..."

As in 10 products in the category. 100? 1,000?

[jpopowski1]

25 or so now.

[Logan Rhodehamel]

To add some more log information, turn on asp.net tracing and post that output as well.

Edit your web.config file. Find the line that sets tracing, and make it look something like this:

Code: Select all

<trace enabled="true" requestLimit="100" pageOutput="false" localOnly="false"/>

Then go browse to a page that gives you a delay problem.

Then go to this URL:

http://yourserver/yourappvirtualdirectoryifany/trace.axd

From this special page, you will see a list of requests made. Go to the view detail link for the ASPX page (e.g. default.aspx) and then you will get some additional debug output. The output that would be most useful is probably the section that gives the processing times:

Code: Select all

Trace Information 
Category Message From First(s) From Last(s) 
 Initializing Request   
 Tick: 162912514 6.944E-05 0.000069 
 Request Initialized 0.19350776 0.193438 
 Tick: 162912717 0.19356212 0.000054 
aspx.page Begin PreInit 5.5060606 5.312498 
aspx.page End PreInit 11.07508896 5.569028 
aspx.page Begin Init 11.07512868 0.000040 
aspx.page End Init 11.32251136 0.247383 
aspx.page Begin InitComplete 11.32255412 0.000043 
 InitComplete, Ensuring Child Controls for ScriptletPart 11.32323848 0.000684 
aspx.page End InitComplete 41.34406428 30.020826 
aspx.page Begin PreLoad 41.34410648 0.000042 
aspx.page End PreLoad 41.34414312 0.000037 
aspx.page Begin Load 41.34416376 0.000021 
 Separator Index: 1 41.67622912 0.332065 
 Separator Index: 3 41.68694588 0.010717 
 Separator Index: 5 41.69029032 0.003344 
aspx.page End Load 41.69204548 0.001755 
aspx.page Begin LoadComplete 41.69206776 0.000022 
aspx.page End LoadComplete 41.6921324 0.000065 
aspx.page Begin PreRender 41.69215068 0.000018 
ASP.layouts_adminpanel_ascx Begin PreRender 42.26905136 0.576901 
ASP.layouts_adminpanel_ascx End PreRender 42.26909176 0.000040 
aspx.page End PreRender 42.26910668 0.000015 
aspx.page Begin PreRenderComplete 42.26912 0.000013 
aspx.page End PreRenderComplete 42.43748828 0.168368 
aspx.page Begin SaveState 42.45203732 0.014549 
ViewState Size 1056b 42.45366468 0.001627 
aspx.page End SaveState 42.45378356 0.000119 
aspx.page Begin SaveStateComplete 42.45379936 0.000016 
aspx.page End SaveStateComplete 42.45383536 0.000036 
aspx.page Begin Render 42.4538484 0.000013 
aspx.page End Render 42.48313204 0.029284

It might gives some more clues.

[jpopowski1]

Biggest delay seems to be in load of a customized category grid page.

aspx.page End LoadComplete 1.80950635351995 0.000027
aspx.page Begin PreRender 1.80952110571656 0.000015
ASP.conlib_giscustom_categorygridpage2_ascx Load Begin 2.1419748603622 0.332454
ASP.conlib_giscustom_categorygridpage2_ascx Load Complete 35.3919018174397 33.249927
ASP.conlib_giscustom_categorygridpage2_ascx Begin Bind Search Results 36.4310584266042 1.039157


It seems like it's the connection (re-connection) to the database.
Running sql traces on the server for the relevant database brings up the same output (just different products) as running on the faster site.

[Logan Rhodehamel]

ASP.conlib_giscustom_categorygridpage2_ascx Load Begin 2.1419748603622 0.332454
ASP.conlib_giscustom_categorygridpage2_ascx Load Complete 35.3919018174397 33.249927

Right there is where to start looking. 33 seconds to process the Page_Load event handler. You can add your own debug information to the trace.axd output by adding this code into your .cs or .vb files:

Code: Select all

Trace.Write("message");

You won't need the semicolon for vb code. If you put those debug markers in your custom control, you might be able to further narrow down what is causing the delay.

[jpopowski1]

Thanks Logan. I will put some trace statements in.

[jpopowski1]

After a time away, I'm still trying to figure out the speed issue. I've put trace statements in the CategoryGridPage2.ascx.cs as follows.

protected void Page_Init(object sender, System.EventArgs e)
{
Trace.Write(this.GetType().ToString(), "Load Begin");
_PageSize = (_Cols * _Rows);
_Category = CategoryDataSource.Load(this.CategoryId);
//EXIT PROCESSING IF CATEGORY IS INVALID OR MARKED PRIVATE
if ((_Category != null) && (_Category.Visibility == CatalogVisibility.Private)) Response.Redirect(NavigationHelper.GetHomeUrl());
if (!Page.IsPostBack)
{
//REGISTER THE PAGEVIEW
CommerceBuilder.Services.AbleCommerceHttpModule.RegisterCatalogNode(this.CategoryId, CatalogNodeType.Category);
Trace.Write(this.GetType().ToString(), "Registered category");
//INITIALIZE SEARCH CRITERIA ON FIRST VISIT
HiddenPageIndex.Value = Request.QueryString["p"];
string tempSort = Request.QueryString["s"];
if (!string.IsNullOrEmpty(tempSort))
{
ListItem item = SortResults.Items.FindByValue(tempSort);
if (item != null) item.Selected = true;
}
}
Trace.Write(this.GetType().ToString(),"Getting content nodes");
//INITIALIZE THE CONTENT NODES
_ContentNodes = new CatalogNodeCollection();
Trace.Write(this.GetType().ToString(),"Got Content Nodes");
foreach (CatalogNode node in _Category.CatalogNodes)
{
Trace.Write(this.GetType().ToString(),"Checking a Node");
if ((node.CatalogNodeType != CatalogNodeType.Category)
&& (node.Visibility == CatalogVisibility.Public))
{
Trace.Write(this.GetType().ToString(),node.Visibility.ToString());
Trace.Write(this.GetType().ToString(),"About to add node");
Trace.Write(this.GetType().ToString(),node.CatalogNodeType.ToString());
_ContentNodes.Add(node);
Trace.Write(this.GetType().ToString(),"Added Node");
}
}
Trace.Write(this.GetType().ToString(), "Load Complete");
}


When I turn on tracing, the longest delay is on this statement
if ((node.CatalogNodeType != CatalogNodeType.Category)
&& (node.Visibility == CatalogVisibility.Public))
You see the 'Checking a node' item, and then a half-second to second delay before the "About to add node".

It's as though getting the info out of the node takes a long time. BTW, this code except for the trace statements is exactly the same as in the vanilla AC code. So, I'm wondering if there's something wrong with our asp.net installation, since accessing the collection must use underlying asp code. Does anyone have an idea how I can test that, and how I can reinstall without affecting the AC installation?

Thanks,
Judy

[AbleMods]

I would suspect this line is the delay...

foreach (CatalogNode node in _Category.CatalogNodes)

Try determining the CategoryId for the _Category instance and then see how many records return in ac_CatalogNodes for that CategoryId. Perhaps the category has an unusual number of nodes in it. Also make sure you have an index in ac_CatalogNodes on CategoryId. Should already be there but might as well double check everything at this point.

The trace below isn't really accurate - got all nodes hasn't happened yet. All that's happened is an empty instance of the CatalogNodeCollection class was created. No data is pulled until the foreach (mentioned above) is hit...

//INITIALIZE THE CONTENT NODES
_ContentNodes = new CatalogNodeCollection();
Trace.Write(this.GetType().ToString(),"Got Content Nodes");

The code itself that you mentioned shouldn't have any delay at all. By that point in the code, the class data should already be populated and comparison to ENUM values would be instantaneous. If you had an issue inside ASP.NET on your server, you'd think the entire site was slow down not particular sections. That's why I think it's the foreach on the line before causing the delay.

Have you checked for orphaned products yet? Now that I think about it, it might be possible to have "orphaned nodes" but I'm not sure.

[igavemybest]

I have one quick, but important suggestion. Try running this site on localhost, and connect to the database also hosted on your own computer. Most hosting companies run their servers at 99.99% capacity. Both CPU, Memory, and disk space. I was starting to have these issues at discountasp.net, and then swithed to arvixe.com and its fast as can be...I have over 160 thousand items in my store. No issues at all. (I dont work for them or have any interest in them). Just try it, see if it is the server speed or you program.

[jpopowski1]

Thank you to Joe Payne and Commander.

I have now deleted all the orphan items.
I also rebuilt the indexes in the database (though this system has only 175 products and 15 categories).
The slow category has 37 products, hardly a large number.

This morning I got an interesting error message that there were two copies of a dll in the temporary internet files.
Since I did nothing yesterday on this system, I'm not sure why that happened, and had to clean it up by
deleting them and letting everything recompile.

[AbleMods]

I'm not sure why that happened, and had to clean it up by
deleting them and letting everything recompile.

That can happen when the site is forced to recompile and something else (browser hit, app pool recycle etc) forces a second recompile before the first has completed. IIS gets confused on which recompile is the latest and throws the exception.

I completely agree that 37 products in a category is not the cause of your problem. More likely additional conlib controls on the page(s) are possibly hitting something more frequently than you realize. Try resetting the page view settings to Able defaults using Able standard scriptlets - does the performance change?

I had an issue recently with my ac_Users table exploding in size - got up to nearly 750,000 records. This caused enormous slowdowns in the oddest places. By adding indices to the users, baskets and basketitems tables I was able to dramatically improve site performance. Then Able helped me clear out the users manually so the table was more reasonable in size.