ASP.NET strange performances trouble

[JohnIdol]

Hi All,

I need to know which functions/classes are involved in some processes I am unable to track via standard debug. Any suggestion about how to profile ASP.NET apps?

Thanks,

JI

In case someone is interested/has time -> Scenario:
I am trying to speed up an existing ASP.NET 1.1 web app.
My major concern is about a procedure which retrieves a small amount of data in a long time (more than 10 seconds for a single row extraction). SQL profiler showed the queries are running ok (even if not omptimized), so I started looking at the actual code.
The code is quite messy, there's a lot going on with an ancient third-Party TreeView being populated on every post back, with a number of unnecessary open connections on every PageLoad, but nothing to slow down things this much. I would change almost everything probably gaining something like up to 5 seconds in total. but here comes my problem: I put a number of breakpoints in order to evaluate where the time was being wasted and surprise -> after all my candidates for being hot-spots finish processing the page keeps mumbling for other 5-6 seconds.

There are only a few things on page so I am pretty much sure I checked almost everything. I have no idea about what's going on and I don't know how to profile it.

[Yeorwned]

Turn tracing on and sort by time.

*.aspx<%@ Page Trace=”true” %>
web.config<configuration>
<system.web>
<trace enabled="true" pageoutput="true" tracemode="SortByTime" />
</system.web>
</configuration>
Refresh the *.aspx page and you will see all tracing information. It may overwhelm you at first glance but give it a chance. Anywhere in the page that you want specific information, you can use Trace.Warn("Event Started") and so forth.

[JohnIdol]

Thanks for replying,

To use tracing I would have to know where to put the "Trace.Warn("Event Started")" statement.

I spent yesterday profiling the app from SQL Profiler and all I could notice is that there's is a significant numebr of un-necessary round trips. All the queries are quite fast (even with recompilation as stored procedures contain lots of temporary tables), the slowest one takes about 760 ms. The query associated to that operation is appearing with duration equals to 0, but there is a lot of crappy traffic before of a lot of other things round-tripping like crazy (< than 3000 ms in total anyway adding durations). I tried to index the DB as well using the Index Tuning wizard and I had something around 30% performance increase (The process in object took 16 seconds before now it takes around 11). I did this as first thing as I didn't develop the app, so before touching the code I wanted to give it a shot.

After this I tracked the data retrieval functions in my code -using breakpoints- and they are executing as expected, confirming the SQL Profiler results. After all the data retrieval is done the application keeps mumbling for a significant amount of time (about 5 secs, maybe some more) and then it displays. It looks like there some background process involved in data processing. I have a couple of user controls on the page; one of those has something like 400 (!) validators and controls.

Any hopinion/suggestion would be appreciated!

JI

[Yeorwned]

You should get all major events without using trace.warn. The only difference is you will won't have the definitive text you specify. That should narrow it down to the general area of latency, which you can then us the warn statements to pick out.

[JohnIdol]

You should get all major events without using trace.warn. The only difference is you will won't have the definitive text you specify. That should narrow it down to the general area of latency, which you can then us the warn statements to pick out.

Ok.
I am getting the trace. It's in the background, so I am not able to read it properly (at the top). Any hint about significant values to look at?

[ronmoles]

Have you checked the web.config file and make sure that debug compilation was not set to true? It would not be the first time someone forgot to modify that before publishing the web site.

Of course, I'm assuming that version of asp.net is the same as 2.0, where I started.

[JohnIdol]

Have you checked the win.config file and make sure that debug compilation was not set to true? It would not be the first time someone forgot to modify that before publishing the web site.

Of course, I'm assuming that version of asp.net is the same as 2.0, where I started.

Hi, thanks for your suggestion.

When you say win.config are you talking about web.config?
If yes, I checked that, but if I set debug to true there's not a very big negative jump of performances.

Now I am trying to understand how to read/interpreter page trace

Cheers,

JI

[Yeorwned]

At the bottom of the page you turned tracing on, do you see the "Trace Information" section which has a category, message, from first, and from last columns? Look for the biggest jumps in time. Since you are saying it takes several seconds, the built-in page method problem child should stick out like a sore thumb.

[JohnIdol]

Thanks for the tips, trace is a great feature I didn'y know about.

I was able to see that some of the controls had a s_hitload of un-necessary viewstate data, as the content is generated every time the page load. I disabled viewState in most of the controls and the loading time dropped from around 12s to around 6s, which is good.

Now I need to kick it down another 3 secs. In my trace I see a call that's the fattiest one:

aspx.page Begin ProcessPostData 0.001328 0.000041
aspx.page End ProcessPostData 0.001442 0.000114
aspx.page Begin ProcessPostData Second Try 2.237838 2.236397 <--

The last guy is taking 2.23 seconds alone. What does that "second try" mean? Any hint about were to look for the guilty process?

Cheers,

JI

[JohnIdol]

Ok, strange behaviour here.

I changed something and managed to reduce overhead and here's the trace:

Trace Information
Category Message From First(s) From Last(s)
aspx.page Begin Init
aspx.page End Init 0.001610 0.001610
aspx.page Begin LoadViewState 0.001678 0.000068
aspx.page End LoadViewState 0.001920 0.000242
aspx.page Begin ProcessPostData 0.001961 0.000041
aspx.page End ProcessPostData 0.002061 0.000100
aspx.page Begin ProcessPostData Second Try 0.960468 0.958407 <---HOT
aspx.page End ProcessPostData Second Try 0.960529 0.000060
aspx.page Begin Raise ChangedEvents 0.960551 0.000022
aspx.page End Raise ChangedEvents 0.960571 0.000021
aspx.page Begin Raise PostBackEvent 0.960591 0.000020
aspx.page End Raise PostBackEvent 0.960615 0.000024
aspx.page Begin PreRender 0.960635 0.000020
aspx.page End PreRender 0.961261 0.000626
aspx.page Begin SaveViewState 1.024631 0.063370
aspx.page End SaveViewState 1.024727 0.000096
aspx.page Begin Render 1.024751 0.000024
aspx.page End Render 1.211487 0.186736


the only hot spot is the one indicated. The total time between begin init and end render is 1.2 s, why in hell it takes about 6 seconds to display?
the browser says "Done" after about 1.5 s, then it keep mumbling for the rest of the time then it displays.

ring any bells?

[Yeorwned]

Do you have lots of client side scripting? Any XMLHttpRequests still getting data?

[JohnIdol]

Do you have lots of client side scripting? Any XMLHttpRequests still getting data?

No XMLhttpRequests.

I figured out there is a very big (in bytes 922326) control populated with LOTS of items. I took out that one from the page and it jumps down near the expected lading time.

This sounds very strange to me as I've seen in the very densely populated ddlists without such an impact on performances.

Any suggestion would be much appreciated!

Thanks,

[Yeorwned]

Is there any codebehind watching for changes to the drop down list? If so, you might be executing x number lines of code each time and entry is added to the datalist during population. That could get real ugly real fast.

[JohnIdol]

Is there any codebehind watching for changes to the drop down list? If so, you might be executing x number lines of code each time and entry is added to the datalist during population. That could get real ugly real fast.

the dropdown is bound to a datareader, so no processing.
I discovered there are 10.000 records in there, so I suppose the delay is due to the client populating the control at rendering time...

[Yeorwned]

You'll just have to rewrite that entirely then to make it perform better. Afterall, a dropdown list looses effectiveness after 10 records and is useless after 50 anyway. Good luck!

[JohnIdol]

You'll just have to rewrite that entirely then to make it perform better. Afterall, a dropdown list looses effectiveness after 10 records and is useless after 50 anyway. Good luck!

I set up a popup with that dropdown alone. It's barely used so this 2secs overhead is acceptable as long as it's not on the main page.

I slowed the loading time down from 16-18 s to 1-3 s... mission accomplished I'd say :-).

Thanks for supporting