Tracing in ASP.NET 2.0
page 1 of 1
Published: 30 Apr 2004
Unedited - Community Contributed
Abstract
The tracing features in ASP.NET 2.0 have not changed all that much from ASP.NET 1.1 or even ASP.NET 1.0. This piece will discuss the additions and changes that have occurred in the ASP.NET Tracing functionality.
by Phil Winstanley
Feedback
Average Rating: This article has not yet been rated.
Views (Total / Last 10 Days): 27909/ 774

Tracing in ASP.NET 2.0
 
This topic is pre-release documentation and is subject to change in future releases.
Tested against Visual Studio .NET 2005, v8.0.40301.9 and the .NET Framework v2.0.40301
 
The tracing features in ASP.NET 2.0 have not changed all that much from ASP.NET 1.1 or even ASP.NET 1.0. This piece will discuss the additions and changes that have occurred in the ASP.NET Tracing functionality.
 
What follows is a summary of the major changes and additions: -
  • A new event has been added to the Trace class, TraceFinished - this fires after the Trace has been Compiled.
  • The timings have been increased in accuracy from 6 Digits to 18 Digits! (This allows for some *really* accurate profiling!)
  • There are now options on how to Sort the Category's of the Trace entries.

And that's about it! So to follow up on the summary this article will explore each of the above changes in Detail.

The TraceFinished Event.

This event and what it lets us do is one of the few Items in the Framework SDK that's actually been populated with information, so below as well as discussing the Event I'll include some of the documentation.

To set up the TraceFinished Event it's just wired up as normal: -

	void Page_Load(object sender, EventArgs e)
	{
		Trace.TraceFinished += new System.Web.TraceContextEventHandler(Trace_TraceFinished);
	}

Then in the Event you can actually Access ALL of your Trace calls in the form of a property on the TraceContextEventArgs object called TraceRecords.

The TraceRecords object contains a collection of TraceContextRecord  objects, which expose the following properties (ms-help://MS.MSDNQTR.v80.en/cpref/html/T_System_Web_TraceContextRecord_Members.htm): -

 Category Gets the user-defined category for the trace record.
 ErrorInfo Gets the Exception associated with the trace record, if one is available.
 IsWarning Gets a value indicating whether the trace record is associated with a System.Web.TraceContext.Warn method call.
 Message Gets the user-defined trace message.

So some sample code to print out these values might look something like this: -

        void Trace_TraceFinished(object sender, System.Web.TraceContextEventArgs e)
	{

		foreach (TraceContextRecord TCR in e.TraceRecords)
		{
			Response.Write(TCR.Message + "<br />");
			Response.Write(TCR.Category + "<br />");
			Response.Write(TCR.ErrorInfo + "<br />");
			Response.Write(TCR.Message + "<br />");
		}

	}        

It's a real shame the timings are not exposed as it would be useful (to me anyway) to be able to Log the Trace to a Database without having to do my own Trace Logging. The Timings would be a great help in spotting parts of your site that start to break down.

Timings 

The best way to show the different timings is to show the HTML it output's, look how long some of those number are! Here's an ASP.NET 2.0 Trace: -

Trace Information

Category Message From First(s) From Last(s)
aspx.page Begin PreInit
aspx.page End PreInit 8.46476297965244E-05 0.000085
aspx.page Begin Init 0.000138285731845807 0.000054
aspx.page End Init 0.000215949233771331 0.000078
aspx.page Begin InitComplete 0.000255060349848933 0.000039
aspx.page End InitComplete 0.000292774640352335 0.000038
aspx.page Begin PreLoad 0.000330768295970577 0.000038
aspx.page End PreLoad 0.000369600046933339 0.000039
aspx.page Begin Load 0.000429663546623942 0.000060
aspx.page End Load 0.000477993711491265 0.000048
aspx.page Begin LoadComplete 0.000515987367109507 0.000038
aspx.page End LoadComplete 0.000553701657612909 0.000038
aspx.page Begin PreRender 0.000591136583001471 0.000037
aspx.page End PreRender 0.000644495319935914 0.000053
aspx.page Begin PreRenderComplete 0.000682768340668996 0.000038
aspx.page End PreRenderComplete 0.000721600091631758 0.000039
aspx.page Begin SaveViewState 0.00226285743020412 0.001541
aspx.page Begin SaveStateComplete 0.00259111144014114 0.000328
aspx.page End SaveStateComplete 0.00263217811202262 0.000041
aspx.page End SaveViewState 0.00266877494206666 0.000037
aspx.page Begin Render 0.0027053717721107 0.000037
aspx.page End Render 0.00326186708087201 0.000556

Compare that to an ASP.NET 1.1 Trace: -

Trace Information

Category Message From First(s) From Last(s)
aspx.page Begin Init
aspx.page End Init 0.000058 0.000058
aspx.page Begin PreRender 0.000114 0.000056
aspx.page End PreRender 0.000161 0.000047
aspx.page Begin SaveViewState 0.000418 0.000257
aspx.page End SaveViewState 0.000535 0.000118
aspx.page Begin Render 0.000605 0.000070
aspx.page End Render 0.001128 0.000522

Sorting Trace Entries

The ASP.NET team have added a new chunk of functinality to ASP.NET 2.0 in the form of being able to sort the contents in the Trace by either Time (which is the Default) or Alphabetically (by the Categories).

The SDK describes this functionality as: -

TraceMode
Indicates how traces messages are to be displayed for the page when tracing is enabled. Possible values are SortByTime and SortByCategory. The default, when tracing is enabled, is SortByTime.

Here is a sample of the Alphabetical Sorting in action: -

	void Page_Load(object sender, EventArgs e)
	{
		Trace.Write("Aardvark", "is Alphabetically First!");
		Trace.Write("Zebra", "is Alphabetically Last :(");
		Trace.Write("Helecopter", "is Somewhere in the Middle Alpahebetically");

		Trace.TraceMode = System.Web.TraceMode.SortByCategory;
	}
        

This Renders a Trace as so - note Zebra is at the end!

Trace Information

Category Message From First(s) From Last(s)
Aardvark is Alphabetically First! 0.000443911167480783 0.000038
aspx.page Begin PreInit
aspx.page End PreInit 9.5263504160445E-05 0.000095
aspx.page Begin Init 0.000142755573683247 0.000047
aspx.page End Init 0.000222095266297812 0.000079
aspx.page Begin InitComplete 0.000259809556801214 0.000038
aspx.page End InitComplete 0.000296965117074936 0.000037
aspx.page Begin PreLoad 0.000333282582004137 0.000036
aspx.page End PreLoad 0.000369600046933339 0.000036
aspx.page Begin Load 0.000405638146747701 0.000036
aspx.page End Load 0.000794514386605001 0.000279
aspx.page Begin LoadComplete 0.000843123916587164 0.000049
aspx.page End LoadComplete 0.000886984239617046 0.000044
aspx.page Begin PreRender 0.000930844562646929 0.000044
aspx.page End PreRender 0.000994539808830452 0.000064
aspx.page Begin PreRenderComplete 0.00105572076898042 0.000061
aspx.page End PreRenderComplete 0.00110013982223998 0.000044
aspx.page Begin SaveViewState 0.00148091447376692 0.000381
aspx.page Begin SaveStateComplete 0.00173848910964941 0.000258
aspx.page End SaveStateComplete 0.00180134626048841 0.000063
aspx.page End SaveViewState 0.0018452065835183 0.000044
aspx.page Begin Render 0.00188878754143334 0.000044
aspx.page End Render 0.00240086379693509 0.000512
Helecopter is Somewhere in the Middle Alpahebetically 0.000515987367109507 0.000036
Zebra is Alphabetically Last :( 0.000480228632409985 0.000036

Okay, that's all for now, there's a quick overrun of the Trace in ASP.NET 2.0.


User Comments

Title: tracefinished event not called when an exception occurs   
Name: Gaurav Tyagi
Date: 5/25/2009 5:18:00 PM
Comment:
I have a .net application that is designed to capture trace output by using the Trace.TraceFinished event. The problem that I am running into is that when an unhandled exception occurres, I am unable to capture the Trace that lead up to the exception because the TraceFinished event is never called.Is there any way to handle it?
Title: Not able to use this for error handling   
Name: Shan McArthur
Date: 11/20/2008 4:52:51 PM
Comment:
It is unfortunate that the timings are not part of the TraceContextRecord class - what a shame. That said, a more important issue for me is that the TraceFinished event is not fired if the page encounters an exception. I would love to be able to dump the page trace out in my custom error handler, but because the event is not fired, and there is no other way to gain access to the current page trace, I cannot get this valuable information. Is anyone aware of another way to gain access to the current trace context that will work within an error handler?
Title: About this article   
Name: Govind Lakal.
Date: 4/15/2007 4:40:09 AM
Comment:
I like this article most and other articles on this side. Just of now I am using this site for getting most of the information about .NET.






Community Advice: ASP | SQL | XML | Regular Expressions | Windows


©Copyright 1998-2014 ASPAlliance.com  |  Page Processed at 8/21/2014 10:02:19 AM  AspAlliance Recent Articles RSS Feed
About ASPAlliance | Newsgroups | Advertise | Authors | Email Lists | Feedback | Link To Us | Privacy | Search