Strange timings

Dans

I have profiled some of my code
long startTime2 = Utils.GetPerformanceCounter();
response = XDocument.Load(request.ToString());
_log.Info(string.Format("Around xdoc load in GetLRReponse {0} ", Math.Round(Utils.GetPerformanceTimeElapsed(startTime2),3)));

In the profiler it says that the XDocument.Load was run twice and took 54.3 seconds
In my log I can see
2008-05-02 11:15:19,806 INFO Ttl.HotelPackages.Services.Hotel.HotelService [(null)] - Around xdoc load in GetLRReponse 13.486


2008-05-02 11:15:29,431 INFO Ttl.HotelPackages.Services.Hotel.HotelService [(null)] - Around xdoc load in GetLRReponse 3.791

I am profiling in detail an app on a local IIS server (.net 3.5) (xp)
I have patched my laptop for the timing issue in the knowledge base and am running single core.

Thoughts?

Dans

long startTime3 = Utils.GetPerformanceCounter();
if (!CacheManager.Exists(key))
{
_log.Info(string.Format("Around cachemanager check in GetLRReponse - took {0} ", Math.Round(Utils.GetPerformanceTimeElapsed(startTime3), 3)));
is returning 2 hits taking 2.32 secs and my logging says
2008-05-02 15:11:31,544 INFO Ttl.HotelPackages.Services.Hotel.HotelService [(null)] - Around cachemanager check in GetLRReponse - took 0.000

2008-05-02 15:11:39,606 INFO Ttl.HotelPackages.Services.Hotel.HotelService [(null)] - Around cachemanager check in GetLRReponse - took 0.000

...there must be some sort of error somewhere or the tool would be of no use at all.....

NB The cache I am using is from the microsoft enterprise library

Brian Donahue

Sorry, but I can't find a sensible explanation for this. On some methods, particularly ones that use lots of recursion, ANTS Profiler's own overhead calculation can inflate the times it reports. This is a longstanding issue which will be significantly minimized in ANTS Profiler version 4, which has a re-worked Intermediate Language instrumentation algorithm that should work much more efficiently.