asp.net profile: not understanding where the time is spent

adbourdages · November 18, 2008 11:43AM

Good day,

I am profiling an asp.net application. In particular, I am testing one page, which is super slow, taking ~8 minutes to run. So, I run ANTS then go to the page and let it execute.

The total time spent to execute the page is ~8 minutes, but when I summarize the results, I get only ~3 minutes spent in the page itself. The main Cassini thread (PerformWaitForCallback) has the full ~8 minutes, then there is Server.OnStart() with ~5 minutes, then my page with ~3 minutes.

When I profile, the only thing I call is the page, so the page processing takes 90% (or more) of the total time the profiler is running. So, why is it reporting that my page takes only ~3 minutes of the ~8 minutes of processing? Is the algorithm under-calculating the time spent in the page or something similar?

If it helps, it is a page that searches a database using EntityFramework, using Cassini.

Actually, I have just realized something: the total time represented by 'PerformWaitCallback() is equal to my page total processing time + the processing time for System.Net.UnsafeNclNativeMethods+SafeNetHandles.accept(). Maybe it is because the socket accept is running simultaneously with the page (after all, it is a web server). That kinda makes sense, but is absolutely useless to me. Is there a way to get the real value for my page execution?

Alain-Daniel

JasonC · November 19, 2008 7:24AM

Yes, I think your analysis is correct. PerformWaitCallback will run for the entire duration of your request. This consists of the two call stacks in the two different threads you identified: one containing OnStart, and the other containing ProcessRequest. You code should all be children of ProcessRequest, which our profiler says takes 3 minutes.

Firstly, if you haven't already, you may wish to change from 'CPU time' to 'Wall-clock time'. This is done by a combo-box in the bottom right corner. This should make both ProcessRequest and OnStart jump up to 8 minutes. This is because I think your code is probably making database calls which cause the ProcessRequest thread to block for a total of 5 minutes during execution. So you code takes 3 minutes of 'CPU time', but 8 minutes of 'Wall-Clock time'. Please get back to me with whether this works.

adbourdages · November 19, 2008 7:42AM

Great, I'll give that a try.

Thanks,
Alain-Daniel

adbourdages · November 19, 2008 8:24AM

Hi,

I did try to change to wall-clock time, but what happened is definitely not what you described. A picture is worth 1000 words, so here are two screen capture of the interface. Note that under wall-clock time, the first thread reports 2500+s which is well over the run time of the profiling session and that the main Page_Load still only reports 166s (you can see the highlighted section at the top, which represents only that page's call).

http://71.6.196.213:82/ForRedGate/cpu-time.png
http://71.6.196.213:82/ForRedGate/wall-clock-time.png

Could you walk me through the data so I can understand it, or is there an bug somewhere as I suspect?

JasonC · November 19, 2008 9:32AM

Thanks for the screenshots! Yes, it is not as I described at all. But I think it can all be explained... somehow.

What caught my eye is the ThreadHelper.ThreadStart, with a hitcount of 1. If you unclick 'Hide Insignificant Methods', what is called within this thread? It appears as if this Thread is responsible for all the wall-clock time that is not used by your Page_Load. However, it has a very low CPU time, which is a bit odd. What going on in ThreadStart?

JasonC · November 19, 2008 9:49AM

Looking at your timeline, there is a suspicious dip in CPU usage at around 7 minutes, followed by around 180s of heavy CPU usage. Perhaps, there is 7 minutes of 'other activity' before your Page_Load? Have you tried selecting various regions within the period 2minutes -> 10 minutes? You may find that Page_load is only run in the last 3 minutes of execution.

Also, you might find RedGate.Profiler.UserEvents.dll. By referencing this dll in your sourcecode, you can make calls to static methods like RedGate.Profiler.UserEvents.SignalEvent("Page_Load is now starting"); These will then appear in your timeline.

Brian Donahue · November 19, 2008 10:11AM

There is a set of instructions for using UserEvents dll in ASP .NET here:

adbourdages · November 19, 2008 1:58PM

All right, lots of info here.

First, about the ThreadStart, there no data in there. I did a graph of the execution tree and it didn't show anything useful:

http://71.6.196.213:82/ForRedGate/threadstart.png

Second, concerning the suspicious dip in CPU usage. It is pretty simple: that is when the web server passes the SQL request to the database and waits for the answer. There are 7 different requests and you can see them all executing. As a proof of that you can check some of the next screen shots and see that the IO shoots after the CPU dip.

Third, I've added user events in my code that fire when (1) at the beginning of Page_Load, (2) at the end of Page_Load, (3) before the search algo starts counting the results, (4) between each of the 7 different SQL queries that makes up the search and (5) during the Unload event.

You will have trouble seeing those events in the following screen shot, but let me describe to you when they happen.
- 1 happens at the beginning of the profile
- followed by 3 which takes a little while
- after each dip you get another event which are the 4s
- then the Unload (5) event triggers.

http://71.6.196.213:82/ForRedGate/with-events-cpu-time.png
http://71.6.196.213:82/ForRedGate/with-events-wall-clock-time.png
http://71.6.196.213:82/ForRedGate/with-events-show-insignificant-methods.png

There are a few things to note:
- the load event and the search processing does indeed take the whole period of the profile, so the cpu-time and wall-clock time should reflect that, but it doesn't
- The run takes ~10 minutes but there is only 181s (cpu: 154s) reportedly spend in OnLoad().
- We can see when the hands off to the db happens, so there is evidence that most of the time is spent before the query executes on the db.

I would also like to mention that running the same page with the same parameters, but not using ANTS, takes ~125s (in debug mode as well). So here we have a little bit of a discrepency:
- test without ANTS: ~125s
- test with ANTS: ~10 minutes

I am expecting ANTS to have an impact on the test, but this is beyond reasonable, isn't it? So I have a theory to explain where the differences between the total execution time of the profiling and the reported cpu-time for the page processing comes from:
- As I mentioned before, I am using EntityFramework (EF) and EntitySQL queries.
- That causes a problem with ANTS (theory): when EF builds the query, there seems to be a collision between it and ANTS that causes it to take 10x longer to execute. (The reason? I don't know, IL injection on both parts? Too many ANTS traps execution due to reflection?)
- On the graphs, we can see that between each CPU dip and IO peak that shows an access to the DB is followed by a long period of high CPU usage. I can show you the code, and there is barely anything happening in the page execution to warrant that CPU usage (the DataBind call is not CPU heavy at all):

#if&#40; DEBUG &#41;
            RedGate.Profiler.UserEvents.ProfilerEvent.SignalEvent&#40;"PerformSearch: dlUser.DataBind&#40;&#41;"&#41;;
#endif
            dlUsers.DataSource = oQueryUser.Skip&#40;dlUsers.PageIndex*dlUsers.PageSize&#41;.Take&#40;dlUsers.PageSize&#41;.ToList&#40;&#41;;
            dlUsers.DataBind&#40;&#41;;
#if&#40; DEBUG &#41;
            RedGate.Profiler.UserEvents.ProfilerEvent.SignalEvent&#40;"PerformSearch: dlTempUser.DataBind&#40;&#41;"&#41;;
#endif
            dlTempUsers.DataSource = oQueryTempUser.Skip&#40;dlTempUsers.PageIndex * dlTempUsers.PageSize&#41;.Take&#40;dlTempUsers.PageSize&#41;.ToList&#40;&#41;;
            dlTempUsers.DataBind&#40;&#41;;

- As you can see, it is: call the DB, databind (which is very simple), then call to the DB. Of course the call to the DB involves the EF to compile the query to sql first, which is where I think there is a problem with EF and ANTS. I can't agree that 10x longer execution time is normal.

So that leads me to conclude that both the ~10m total execution time and the ~154s page processing time are right. Yes, indeed, the ~8 extra minutes was due to ANTS overhead during EF query compile. So the tool is reporting ~154s correctly since ANTS uses a time-correction algorith to take its presence out the of equation as much as possible. 154s is barely different than the ~125s for the test without ANTS.

As far as finding the cause of the slowness of the page, I've discovered, hidden under many function calls, that the function PlanCompiler.Compile for the EF is responsible for ~135s of the ~154s execution time. (I am saying this in case anyone searches the forums and hopes to find an answer to a similar problem). I don't know what to do with that, but at least the problem is pinpointed.

http://71.6.196.213:82/ForRedGate/ef-time.png

I would like to know however, if the 10x slowdown I experience is typical of the use of ANTS or if it is related to EF or if it is a bug.

Regards,
Alain-Daniel

JasonC · November 20, 2008 5:44AM

Excellent! I'm glad ANTS Profiler has been able to (eventually) identify the problem. But anyway...

Between every IL branchpoint (which may be every line), ANTS Profiler instruments the IL to record the current time. This introduces an overhead of about 10ns per IL statement. Consequently, this slows down a typical program by around 3x. However, for programs with tight loops, lots of mathematics, or lots of method calls, this can be higher (e.g. 10x). You seem to be experiencing a 10x slowdown.

Compiling a SQL query is the kind of thing that introduces a lot of overhead. I imagine there are deep recursive methods, tight loops, etc - the kind of stuff ANTS Profiler hates. However, I've done some research and I'm pretty sure ANTS Profiler is the fastest line-level instrumentation profiler out there. Rivals were typically 2x to 40x slower than ANTS. I'm sorry that you've got a program that is as slow as possible for our profiler! To speed up profiling, I can suggest turning on Inlining in our options dialog, or profiling in method-level rather than line-level mode.

ANTS Profiler estimates and subtracts the overhead, hopefully leaving you with realistic results. So the fact it takes 100s outside the profiler, and ANTS says it takes 125s, is correct.

I don't think what you've seen is a bug. I think it's just that EF is a worst-case scenario for ANTS Profiler's speed.

StephenC · November 20, 2008 6:38AM

Just to add briefly to the overhead comments,

we will be introducing another profiling mode next year which will allow the profiling at the line level but only methods with source. This will reduce the amount of overhead when profiling a project where there are deep recursive calls to methods without source like when working with other frameworks, datasets etc...

Stephen

asp.net profile: not understanding where the time is spent

Comments

Product Learning

Community Forums

Events & Friends

Simple Talk