How do I increase information in ASP.NET Trace

Question

I've made some performance improvements to my application's backend, and to show the benefit to the end users of the GUI, we've been using the Trace.axd page to take timings. (The frontend is .Net 1.1 and the backend is Java, connected via Web services.)

However, these timings show no difference between the old and the new backends.

By putting a breakpoint in the backend and holding a request there for 30 seconds, I can see from Trace.axd that the POST is taking 3ms, and the GET is taking 4s. I'm missing about 26s...

The POST is where the performance improvement should be, but the timing on the Trace page seems to only include the time it takes to send the request, not the time it takes to return.

Is there a way to inrease the granularity of the information in the trace to include the whole of the request? Or is there another way to take the measurements I need?

Answer 1

I'm not sure how you're making the requests on the .NET side, but I'll assume that there's a HttpWebRequest involved somewhere. I'd expect HttpWebRequest.GetResponse() to return as soon as it has received the response headers. That way, you can start processing the start of a large response while the rest is still downloading. If your trace messages are immediately before and after a call to GetResponse, you therefore wouldn't see the whole execution time of the backend. Can you add a trace message immediately after you close the response?

Answer 2

It is abnormal that the trace output doesn't show all the time you've spent in the brakpoint. Did you check the total time column to see if it matches the time you've spent in the request ? Don't forget that one of the columns only shows the time spent since the preceeding trace statement.

If you want more granular data in the trace output, you can add your own. The TraceContext class has two methods, Warn and Write that add lines to the output (warn adds it in red).

The TraceContext is accessible from every page or control: just use this.Trace.Warn() or this.Trace.Write() (and I think it is also accessible through the HttpContext class).

Answer 3

OK, I kind of got what I wanted in the end. The problem is the IIS Trace doesn't include the time the POST takes to return.

I found that I could use Trace.Write() to add custom entries to the trace log, and even add a category, using Trace.Write(string category, string message).

Adding a call to Trace.Write() in my code that executes after the POST has completed gives me a better figure.

Still, it's not ideal as it's custom, and it's down to me to put it as near to the end of the POST cycle as possible.