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.