Plip's Weblog

Phil Winstanley - British .NET chap based in Lancashire. Enjoys tea and tech. Working for Microsoft.

Tracing in ASP.NET

Tracing in ASP.NET

 

This small article will focus on ASP.NET’s built in Tracing functionality, this offers the developer a place to put all the debug information from their program without it mucking up your expertly designed UI (well I can dream!).

 

We will discuss the benefits of using Trace, as well as the costs it imposes on you as the developer – especially in a team based environment. There is also a special section of this article devoted to the classic ASP developers that know and love Response.Write, hopefully I can persuade you not to use it any more J

 

The .NET Documentation describes Tracing as so: -

ASP.NET introduces new functionality that allows you to write debug statements, directly in your code, without having to remove them from your application when it is deployed to production servers. Called tracing, this feature allows you to write variables or structures in a page, assert whether a condition is met, or simply trace through the execution path of your page or application.

In order for these messages and other tracing information to be gathered and displayed, you must enable tracing for the page or application. When you enable tracing, two things occur:

  • ASP.NET appends a series of diagnostic information tables immediately following the page's output. The information is also sent to a trace viewer application (only if you have enabled tracing for the application).
  • ASP.NET displays your custom diagnostic messages in the Trace Information table of the appended performance data.

Diagnostic information and tracing messages that you specify are appended to the output of the page that is sent to the requesting browser. Optionally, you can view this information from a separate trace viewer (trace.axd) that displays trace information for every page in a given application. This information can help you to clarify errors or undesired results as ASP.NET processes a page request.

Trace statements are processed and displayed only when tracing is enabled. You can control whether tracing is displayed to a page, to the trace viewer, or both.


Turning it on

What I shall show you first is simply how to turn tracing on for one of your existing ASP.NET pages.

First find the Page directive on your ASP.NET page (usually the first line in the page): -

<%@ Page language="c#" Codebehind="default.aspx.cs" AutoEventWireup="false" Inherits="intranet._default" %>

Now we need to turn on Tracing for your page, we do this by adding the Trace property to the directive and setting it to true, like this: -

<%@ Page language="c#" Codebehind="default.aspx.cs" AutoEventWireup="false" Inherits="intranet._default" Trace=”True” %>

Save your page, and open it in a browser. You should see the trace information at the bottom of the page looking something like this: -

If you are not seeing the Trace information then take a quick look through this checklist to make sure something isn’t overriding your settings.

Note you can also enable tracing in your application, at an application level.


What’s in it?

Request Details

Trace Information

Control Tree

Session Collection

Cookies Collection

Forms Collection

Headers Collection

Server Variables


How does it work with my page HTML?

As soon as ASP.NET detects the </html> tag is in the response buffer it adds the Trace information to the end of the page, this is all encapsulated in a <div> with an id of __asptrace.

Talk about absolute positioning
Let’s use it to help us Debug a page

Visual Studio .NET and ASP.NET offer the developer some really cool debugging tools, but if you don’t have access to them, then you are stuck with the good old ways of doing things, writing out your variables until you find the problem.

Let’s just quickly throw together some business logic that has a variable changing it’s value through out the page, in real life this could be anything from the content of a shopping basket right up to some high level mathematics. For now it’s just me playing around with a number.

private void Page_Load(object sender, System.EventArgs e)

{

          //Some fake business logic

 

          //Take a variable, any variable

          int i = 0;

 

          //Perform some addition

          i += 10;

 

          //Perform some more addition

          i += 30;

 

          //Do something slightly more complex than addition

          i = (i * (i + -2));

 

          //Pass it to a method

          i = DoSomething(i);  

 

}

 

public int DoSomething(int aNumber)

{

         

          //Blow up, just to prove a point

          if (aNumber > 0)

          {

                   throw new Exception("aNumber is more than 0!");

          }

          else

          {

                   //Set it to 0

                   return 0;

          }

 

}

In the Page_Load event we can see how we’re changing the value of i quite a bit. If something is going wrong like this: -

Trace Information

Category

Message

From First(s)

From Last(s)

 

 

 

 

 

 

aspx.page

Begin Init

 

 

 

 

 

 

 

 

aspx.page

End Init

0.001180

0.001180

 

 

 

 

 

 

Unhandled Execution Error


aNumber is more than 0!
  at intranet._default.DoSomething(Int32 aNumber) in c:\inetpub\wwwroot\intranet\default.aspx.cs:line 56
  at intranet._default.Page_Load(Object sender, EventArgs e) in c:\inetpub\wwwroot\intranet\default.aspx.cs:line 44
  at System.Web.UI.Control.OnLoad(EventArgs e)
  at System.Web.UI.Control.LoadRecursive()
  at System.Web.UI.Page.ProcessRequestMain()

0.002194

0.001014

 

 

 

 

 

 

This gives us no information as to where our sums are going wrong, so we can use the Trace commands to output the variables value throughout it’s life time.

So here is the same method above with some Trace calls: -

private void Page_Load(object sender, System.EventArgs e)

{

          //Some fake business logic

 

          //Take a variable, any variable

          int i = 0;

 

          Trace.Write("i","Variable after it's been created is " + i.ToString());

 

          //Perform some addition

          i += 10;

 

          Trace.Write("i","Variable after it's been added to is " + i.ToString());

 

          //Perform some more addition

          i += 30;

 

          Trace.Write("i","Variable after it's been added to again is " + i.ToString());

 

          //Do something slightly more complex than addition

          i = (i * (i + -2));

 

          Trace.Write("i","Variable after it's been messed around with is " + i.ToString());

 

          //Pass it to a method

          i = DoSomething(i);  

 

          Trace.Write("i","Variable after it's been processed is " + i.ToString());

 

}

 

public int DoSomething(int aNumber)

{

         

          //Blow up, just to prove a point

          if (aNumber > 0)

          {

                   throw new Exception("aNumber is more than 0!");

          }

          else

          {

                   //Set it to 0

                   return 0;

          }

 

}

When we run our page with the Trace information included we get it all placed in to the Trace log: -

Trace Information

Category

Message

From First(s)

From Last(s)

 

 

 

 

 

 

aspx.page

Begin Init

 

 

 

 

 

 

 

 

aspx.page

End Init

0.001043

0.001043

 

 

 

 

 

 

i

Variable after it's been created is 0

0.002366

0.001323

 

 

 

 

 

 

i

Variable after it's been added to is 10

0.002413

0.000047

 

 

 

 

 

 

i

Variable after it's been added to again is 40

0.002442

0.000030

 

 

 

 

 

 

i

Variable after it's been messed around with is 1520

0.002472

0.000030

 

 

 

 

 

 

Unhandled Execution Error


aNumber is more than 0!
  at intranet._default.DoSomething(Int32 aNumber) in c:\inetpub\wwwroot\intranet\default.aspx.cs:line 56
  at intranet._default.Page_Load(Object sender, EventArgs e) in c:\inetpub\wwwroot\intranet\default.aspx.cs:line 44
  at System.Web.UI.Control.OnLoad(EventArgs e)
  at System.Web.UI.Control.LoadRecursive()
  at System.Web.UI.Page.ProcessRequestMain()

0.003193

0.000720

 

 

 

 

 

 

Now we can see by looking at the trace log, what’s happening to the number, and we can modify our business logic accordingly.

private void Page_Load(object sender, System.EventArgs e)

{

          //Some fake business logic

 

          //Take a variable, any variable

          int i = 0;

 

          Trace.Write("i","Variable after it's been created is " + i.ToString());

 

          //Perform some addition

          i += 10;

 

          Trace.Write("i","Variable after it's been added to is " + i.ToString());

 

          //Perform some more addition

          i += 30;

 

          Trace.Write("i","Variable after it's been added to again is " + i.ToString());

 

          //Do something slightly more complex than addition

          i = (i * -(i + -2));

 

          Trace.Write("i","Variable after it's been messed around with is " + i.ToString());

 

          //Pass it to a method

          i = DoSomething(i);  

 

          Trace.Write("i","Variable after it's been processed is " + i.ToString());

}

Now when we look at the page the exception does not occur and we can see why when we look at the Trace information: -

Trace Information

Category

Message

From First(s)

From Last(s)

 

 

 

 

 

 

aspx.page

Begin Init

 

 

 

 

 

 

 

 

aspx.page

End Init

0.003425

0.003425

 

 

 

 

 

 

i

Variable after it's been created is 0

0.006264

0.002838

 

 

 

 

 

 

i

Variable after it's been added to is 10

0.006327

0.000063

 

 

 

 

 

 

i

Variable after it's been added to again is 40

0.006370

0.000044

 

 

 

 

 

 

i

Variable after it's been messed around with is -1520

0.006414

0.000044

 

 

 

 

 

 

i

Variable after it's been processed is 0

0.007609

0.001195

 

 

 

 

 

 

aspx.page

Begin PreRender

0.007684

0.000074

 

 

 

 

 

 

aspx.page

End PreRender

0.009410

0.001727

 

 

 

 

 

 

aspx.page

Begin SaveViewState

0.034088

0.024677

 

 

 

 

 

 

aspx.page

End SaveViewState

0.085753

0.051665

 

 

 

 

 

 

aspx.page

Begin Render

0.085834

0.000081

 

 

 

 

 

 

aspx.page

End Render

0.288975

0.203141

 

 

 

 

 

 

Now we have fixed our code, we don’t need to do anything to the Trace commands as they do not interfear with the visual side of our page. All we need to do is set the Trace property to false in the page directive Tag.

<%@ Page language="c#" Codebehind="default.aspx.cs" AutoEventWireup="false" Inherits="intranet._default" Trace="False" %>


Which part of “False” do you not understand?

Remember way back to the top of the article, where I showed you an excerpt from the .NET SDK Documentation, it said “Trace statements are processed and displayed only when tracing is enabled.”?

It Lies. J

We can prove this by setting the Trace property on a page to False and then calling a trace command that will cause an exception, for example referencing an object that doesn’t exist such as a Querystring value: -

private void Page_Load(object sender, System.EventArgs e)

{

          Trace.Write(Request.QueryString["Doesn'tExist"].ToString());

}

 

Calling this when Trace is enabled causes an exception to occur: -

Server Error in '/intranet' Application.


Object reference not set to an instance of an object.

Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code.

Exception Details: System.NullReferenceException: Object reference not set to an instance of an object.

Source Error:

 
Line 21: {
Line 22:         //Some fake business logic
Line 23:         Trace.Write(Request.QueryString["Doesn'tExist"].ToString());
Line 24: }
Line 25: 


Source File: c:\inetpub\wwwroot\intranet\default.aspx.cs    Line: 23

Stack Trace:

 
[NullReferenceException: Object reference not set to an instance of an object.]
   intranet._default.Page_Load(Object sender, EventArgs e) in c:\inetpub\wwwroot\intranet\default.aspx.cs:23
   System.Web.UI.Control.OnLoad(EventArgs e) +67
   System.Web.UI.Control.LoadRecursive() +29
   System.Web.UI.Page.ProcessRequestMain() +718

 


Version Information: Microsoft .NET Framework Version:1.0.3705.288; ASP.NET Version:1.0.3705.288

This means that the statement “Trace statements are processed and displayed only when tracing is enabled.” is obviously a blatant lie.

This is also important in terms of costly operations, lets say you’ve put a large loop in to your page and it’s outputting data to the Trace log so you can debug it – why do we need to call this when Trace is turned off?

A solution is provided in the form of Trace.IsEnabled(), we can check to see if Tracing is enabled before we run the Trace commands, like this: -

private void Page_Load(object sender, System.EventArgs e)

{

          if (Trace.IsEnabled)

          {

                   Trace.Write(Request.QueryString["Doesn'tExist"].ToString());

          }

}

Now, that means we now have to write four lines of code for every Trace we have to write, which is really not an inviting thought – Trace is supposed to make things EASIER not HARDER!

Let’s also add some error handling to our Trace command to make sure that even when we get errors we can handle them properly: -

private void Page_Load(object sender, System.EventArgs e)

{

          if (Trace.IsEnabled)

          {

                   try

                   {

                             Trace.Write(Request.QueryString["Doesn'tExist"].ToString());

                   }

                   catch (Exception ex)

                   {

                             Trace.Warn("Trace","Exception",ex);

                   }

          }

}

Now, our simple 1 line Trace.Write call is 11 lines long! Messy I hope you’ll agree.


Tidy the Mess

The easiest and quickest way to get around these limitations of Trace is to encapsulate all the functionality so that we can call it in one line. One way to do this is to create a class such as so.

using System;

namespace My

{

          public class Trace

          {

                   public static void Write(string Message)

                   {

                             if (System.Web.HttpContext.Current.Trace.IsEnabled)

                             {

                                      try

                                      {

                                                System.Web.HttpContext.Current.Trace.Write(Message.ToString());

                                      }

                                      catch(Exception e)

                                      {

                                                System.Web.HttpContext.Current.Trace.Warn("Intranet.Web","Write",e);

                                      }

                             }

                   }

                   public static void Write(string Category, string Message)

                   {

                             if (System.Web.HttpContext.Current.Trace.IsEnabled)

                             {

                                      try

                                      {

                                                System.Web.HttpContext.Current.Trace.Write(Category.ToString(),Message.ToString());

                                      }

                                      catch(Exception e)

                                      {

                                                System.Web.HttpContext.Current.Trace.Warn("Intranet.Web","Write",e);

                                      }

                             }

                   }

                   public static void Write(string Category, string Message, System.Exception exe)

                   {

                             if (System.Web.HttpContext.Current.Trace.IsEnabled)

                             {

                                      try

                                      {

                                                System.Web.HttpContext.Current.Trace.Write(Category.ToString(),Message.ToString(),exe);

                                      }

                                      catch(Exception e)

                                      {

                                                System.Web.HttpContext.Current.Trace.Warn("Intranet.Web","Write",e);

                                      }

                             }

                   }

                   public static void Warn(string Message)

                   {

                             if (System.Web.HttpContext.Current.Trace.IsEnabled)

                             {

                                      try

                                      {

                                                System.Web.HttpContext.Current.Trace.Warn(Message.ToString());

                                      }

                                      catch(Exception e)

                                      {

                                                System.Web.HttpContext.Current.Trace.Warn("Intranet.Web","Write",e);

                                      }

                             }

                   }

                   public static void Warn(string Category, string Message)

                   {

                             if (System.Web.HttpContext.Current.Trace.IsEnabled)

                             {

                                      try

                                      {

                                                System.Web.HttpContext.Current.Trace.Warn(Category.ToString(),Message.ToString());

                                      }

                                      catch(Exception e)

                                      {

                                                System.Web.HttpContext.Current.Trace.Warn("Intranet.Web","Write",e);

                                      }

                             }

                   }

                   public static void Warn(string Category, string Message, System.Exception exe)

                   {

                             if (System.Web.HttpContext.Current.Trace.IsEnabled)

                             {

                                      try

                                      {

                                                System.Web.HttpContext.Current.Trace.Warn(Category.ToString(),Message.ToString(),exe);

                                      }

                                      catch(Exception e)

                                      {

                                                System.Web.HttpContext.Current.Trace.Warn("Intranet.Web","Write",e);

                                      }

                             }

                   }

          }

}

If you place the above in to a class file in your project, you can then use it as a 1 line replacement for Trace as so: -

private void Page_Load(object sender, System.EventArgs e)

{

          if (Request.QueryString["Doesn'tExist"] != null)

          {

                   My.Trace.Write(Request.QueryString["Doesn'tExist"].ToString());

          }

}

 

This is all nice and neat and encapsulated now, and gives you a performance increase which scales with your application through debug and in to release, as well as error handling of your Trace commands, all this with the ease of use of the Trace methods them selves.

Posted: Apr 11 2004, 09:30 AM by Plip | with 3 comment(s)
Filed under:

Comments

enableDeepak said:

quiet easy to understand. good!

# September 2, 2008 4:38 AM

mellamokb said:

This means that the statement “Trace statements are processed and displayed only when tracing is enabled.” is obviously a blatant lie.

Um,.. no.  The invalid code Request.QueryString["Doesn'tExist"].ToString() will yield a NullReferenceException whether it's embedded inside a method call or not.  As you can see in the stack trace, the error occurred before it even reached the point of processing Trace.Write.

# February 9, 2011 5:16 PM