How can we help you today? How can we help you today?
adbourdages
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( DEBUG ) RedGate.Profiler.UserEvents.ProfilerEvent.SignalEvent("PerformSearch: dlUser.DataBind()"); #endif dlUsers.DataSource = oQueryUser.Skip(dlUsers.PageIndex*dlUsers.PageSize).Take(dlUsers.PageSize).ToList(); dlUsers.DataBind(); #if( DEBUG ) RedGate.Profiler.UserEvents.ProfilerEvent.SignalEvent("PerformSearch: dlTempUser.DataBind()"); #endif dlTempUsers.DataSource = oQueryTempUser.Skip(dlTempUsers.PageIndex * dlTempUsers.PageSize).Take(dlTempUsers.PageSize).ToList(); dlTempUsers.DataBind(); - 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 / comments
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/threads...
0 votes