Application slows down while profiling (+incorrect results)

sebbie

I've downloaded demo version of ANTS Profiler. I'm trying to profile ASP.NET 2.0 application. I'm getting incorrect results. The slowest lines in my app are
- While xmlTr.Read() ' according to ANTS this is taking 4.51sec
- If xmlTr.NodeType = XmlNodeType.EndElement And xmlTr.Name = "xxx" ' this is taking 2.9sec
- If readProcess = True And xmlTr.NodeType = XmlNodeType.EndElement And xmlTr.Name = "ActivitySets" ' this is taking 2.83sec
where xmlTr is XmlTextReader class object.

ANTS Profiler claims method reading configuration file is taking 12sec:

(...) 12.5101 12.6596 28 XmlReader.vb

After I turn off ANTS profiler and do simple logging to file it turns out:
2006-11-13 12:39:38 2964ms

---

(...): read process start
2006-11-13 12:39:38 5153ms

---

(...): read process ended

So, profiler is saying that I'm executing my code in 12.5sec, with detached profiler I'm executing it in ~0.220sec.

So it seems that profiler is wrong about my code. It's very noticable that application is running dramatically slower with profiler, especially when it's re-reading configuration file.

Am I doing something wrong?

I'm using trial version of ANTS profiler 2.7.1.20.

Brian Donahue

Hi Sebbie,

I can't comment because I do not understant the competitive methods that you are using to compare your timiongs against ANTS Profiler. If anyone else has run similar tests and would care to comment, you're more than welcome to here.

sebbie

The competetive method to ANTS profiler is lame one :
1) Log current timestamp (DateTime.Now) to file (open file for appending, write, flush and close file)
2) Execute method I'm trying to profile
3) Log current timestamp (DateTime.Now) to file (open file for appending, write, flush and close file)

Method I'm trying to profile reads configuration data from XML file using XmlTextReader. With ANTS profiler attached method is executing in 12seconds and without it it's executing in ~0.2sec. Method looks like that:

While xmlTr.Read()
If xmlTr.NodeType = XmlNodeType.EndElement And xmlTr.Name = "xxx" ...
If myVar= True And xmlTr.NodeType = XmlNodeType.EndElement And xmlTr.Name = "yyy"
etc.
End While

So basically it's just reading and parsing XML document. Difference between 0.2 and 12sec is too big and I can't profile my application because of that.

Hope that's clearer

Tom Harris

Hi there,

i'm sorry that you are running into problems. I suspect that we still have a problem with reading xml files. The timing discrepancy may well be caused by the use of recursion within the .NET Framework System.Xml namespace. I will attempt to create a sample application here that exhibits the same phenomena.

Best regards,

Tom Harris

Tom Harris

Hi there,

we have just run a sample app that loads a very large xml document. You are correct that the timings are massively exaggerated. Unfortunately this is due to the enormous number of method calls that happen underneath in the System.Xml namespace. We will be looking to change this behaviour in the next version of the product.

Apologies,

Tom Harris

Red Gate Software

rick.garibay@ess-home.com

Tom Harris wrote:

We will be looking to change this behaviour in the next version of the product.

Man, this is a deal breaker for us. Otherwise this is a fantastic tool. Any chance for a hotfix before the next release?