In my latest article here at VB-2-The-Max (“COM+ Centric Assert“) I promised to deliver a three-part article about tracing. Here I am. Santa Claus is fulfilling your wish list for goodies, I take care of the programming stuff.

In this first part I will start with a general discussion about tracing and then discuss how trace calls can be sent from your stored procedures in SQL Server. On the way I will also briefly discuss a client tool for viewing the trace messages. In part two I will focus on tracing the execution of configured COM+ components and in the third part I will discuss tracing in ASP and talk a little more about the client tool.

Before I discuss tracing in the context of stored procedures, let’s start by giving an overview of the complete article.

PURPOSE OF THIS ARTICLE

Some of you are probably thinking that you don’t need to see another solution for tracing today, especially not since the .NET Framework has a nice one built in. On the other hand, I guess that most of you will delay using, VB.NET, for example, in production until next autumn at least, and perhaps you have applications that need to be built (and debugged) today?

If you use something like the trace solution that I will discuss in those three parts, it will be easy to port to the .NET solution since it’s highly centralized. (I bet you will have a much harder time with porting a lot of other stuff!) As always I find centralization and generalization of code important to get a solution that is manageable.

I will give you a concrete proposal in this article that you can use as is, to get inspiration from for building a better one or to extend to better fit your needs. My main purpose isn’t to give you a quickly hacked tracing solution. My main purpose is rather to stress the concept of tracing and get you to start using tracing in any way you find appropriate.

WHY TRACING?

In the software engineering field there is a lot of discussion about “abilities” such as scalability, maintainability, portability, testability and even performability. I asked a friend who is a researcher in software architectures if they were talking about “debuggability” too, but he had never heard of it. He immediately understood what I meant, but perhaps I invented that word. I’m so proud.

What I mean by debuggability is preparing your application for easy and efficient debugging when it is needed. There are several things you should do, but the single most important technique in my opinion is to add tracing support so that your application can tell you what is going on.

Perhaps you recognize the situation when your customer is calling you and he says he has a problem with the application you have built. Since it seems to be a strange problem, the only answer you can give him is that you will have to add tracing to the application and send him a new version in a couple of days. You (and your customer) are in a much nicer situation if you could just tell him to “do that” to turn trace calls on, run the scenario and send you the trace log. You haven’t solved the problem yet, but you made a very quick start!

The interactive debuggers that we are now accustomed to should of course be used as much as possible, but they have shortcomings that tracing can help to solve. Examples include easier debugging of multi-user scenarios and debugging on-line without interfering (too much) with the system. With a tracing tool you will also get a better overview when you start debugging than with a debugger, where you’re in detail mode directly.

VB’s debugger works best for debugging the application in the IDE and not the executable. If you like to debug the executable, Visual Studio’s debugger is a better choice, but even that one prefers to have an executable that isn’t optimized, for example. One way of comparing debuggers with tracing is that debuggers are better early in the project’s life cycle and tracing tools are better late. Another reason for this is that it’s quite common that the customer doesn’t allow you to install Visual Studio on any of his production servers.

You will also get primitive profiling capabilities for free when you use a tracing tool. That way you can see where most of the time is spent in your code and where you should spend your optimization resources. No, a simple trace tool does not make it possible to skip a real profiling tool, for example, for checking the code coverage of your testing, but I use it quite often for quickly finding bottlenecks.

Another use for your trace logs will be to use them for review. I really like the idea of design and code review, and reading trace logs are sort of taking it to the next level. Once when I gave my course “COM+ Component Services and VB”, one of the attendees had an idea when I talked about tracing. He said that it would be quite simple to use the trace log to automatically check if the documentation he had created as activity diagrams in Rational Rose was correct. That would be one way of getting better documentation and documentation that has evolved with the system.

TRACE WHAT?

I’ve decided to categorize my trace messages the following way:

• Assert
• Begin
• End
• Error
• Msg

“Assert” should be used in your assert-sub (as I discussed in “COM+ Centric Assert“) for sending signals about broken assertions as trace-calls. “Begin” and “End” should be used when a procedure is entered and exited.

“Error” should be used in your general sub where you raise errors. You shouldn’t skip ordinary logging of errors to the event log, a database or something like that just because you send trace-calls. Think about trace calls as something that might be activated and that somebody might be listening to. Error logging should always be active so that information can be used afterwards even if no one was actively listening at the moment when the problem occurred.

Finally “Msg” should be used at specific places in the code where you like to take a look at certain variable values or say that a certain section in code was entered.

WISH LIST AND DESIGN GOALS OF MY TRACE SOLUTION

Something like a year ago I decided on the following requirements and design goals for my tracing solution:

• Collect information from ASP, COM+ components and stored procedures in SQL Server

  I’d like to have the possibility to view the calls from my ASP page, some subs/functions in an ASP include layer, then through all the layers in COM+ and finally to the stored procedures in SQL Server. That way I will get a good understanding of what is going on, no matter which server process the problem lies in.

• Make it possible to view information from several servers as one single trace log

  What I said in the previous bullet should be true even if the processes are spread over several physical machines.

• Activation/deactivation online

  It’s preferable that you can have a single version of the executable so that you don’t have to swap a DLL, for example, before you can start tracing. When you decide that you need to start to trace something, you should be up and running in a minute.

• Small overhead, especially important when not activated

  The overhead should be small when the tracing support isn’t activated but is only there waiting to be activated. It should be possible to easily strip out the tracing support when the system has been running smoothly for a while. The trace calls shouldn’t be deleted from the source file, but excluded only from the executable.

  It’s very important to make your debug tools interfere as little as possible. That goes for your assertions and your trace calls as well. If you get side effects from those, then they will create problems of their own or they may hide problems that appear when the debuggability tools are taken away (for example with conditional compilation).

• Filtering possibilities

  You will very quickly collect a lot of tracing information so it’s necessary to have the possibility to filter the trace information. This applies both before the trace calls are sent and in the client tool, where the trace calls should be shown.

• Easy to use for developers

  It should be easy to activate/deactivate tracing, but also easy to do the trace calls in your code.

• Carry a lot of information with each trace call

  It’s also important to send specific data to get consistent trace information when it’s time to analyze the data. The name of the procedures, process ID, thread ID, hostname and so on should always be added. The same goes for more COM+ centric stuff such as IsInTransaction and IsSecurityEnabled.

I created the first version of my tracing tool a year ago so I guess it was quite OK directly, regarding my needs. OK, I confess that I have made some small changes to the stored procedure version recently and I will make some small changes to the COM+ solution and the client tool too, before I write parts two and three of the article.

A CLIENT TOOL

You will also need a tool for capturing all the trace calls. Below you can see a screen shot of my own such tool after it has captured a call from an ASP page to an ASP include, through three COM+ layers and then to a stored procedure. Look at the type column and you can see that first all the different layers are entered and then they are left. In the stored procedure a “Msg” trace call was also sent and the value of the parameter @vintId was inspected.

Fig 1 Screen shot of jnskTraceView

The tool is very simple, but there is still some stuff I’d like to describe further in the third part of this article. Before I write that part of the article, I will upgrade this tool. I wrote the current version early this year (2000), and it works, but I have several small things I’d like to (and must) fix real soon… Anyway, you will find this tool together with the rest of the tools discussed in this part in the download, see SUPPLEMENTAL FILES below.

OVERALL ARCHITECTURE

I decided to use the Win32 API procedure OutputDebugString (ODS) as the mechanism for sending my trace calls. Those calls can then be collected by, for example, the Visual Studio Debugger but also by my client tool.

If you like to use the procedure in VB, you declare it this way:

Private Declare Sub OutputDebugString _
Lib "kernel32" Alias "OutputDebugStringA" _
(ByVal lpOutputString As String)

And then you can use it like this:

OutputDebugString "Hello World!"

In my tracing solution I will send a string with all the needed information separated by tabs. Since every piece of data will be in a specific “column” of the row, it’s easy to parse the row and do whatever I like to do with it.

A drawback of using ODS is that there are several other programs (such as SQL Server and IIS) that are calling the same procedure too. Therefore one of the filter options in the client tool is to only show the calls that were created by my routines.

HOW ABOUT SQL SERVER?

Let’s leave the general stuff about the complete article and dig further into the details of how to add tracing to your stored procedures in SQL Server.

I have a collection of stored procedures named like this:

• jnskTraceAssert
• jnskTraceBegin
• jnskTraceEnd
• jnskTraceError
• jnskTraceMsg
• jnskTraceWrite

The signatures of the “Begin” procedure look like this:

CREATE PROCEDURE jnskTraceBegin 
(@vstrSource VARCHAR(255))

The only information that needs to be sent is the name of the stored procedure that was entered.

The signature of the “Msg” procedure is only slightly larger:

CREATE PROCEDURE jnskTraceMsg
(@vstrSource VARCHAR(255),
@vstrMsg VARCHAR(255)) 

Here a parameter is added with the variable name and its value.

The last stored procedure, jnskTraceWrite, could be used by all the other trace procedures for centralizing the final call to OutputDebugString. Yes, I know that I can’t call the Win32 API directly from stored procedures, but there are other alternatives.

IMPLEMENTATION VARIANT ONE: COM AUTOMATION

If I want to call OutputDebugString from my stored procedures there are several possibilities and I will discuss two of those a little further.

It’s quite simple to wrap the call in a COM component and then use COM Automation (or OLE Automation as SQL Server still calls it) from the stored procedures to instantiate the component and call a method. I have created a COM component called jnskTraceSrv and its only method has the following signature:

Public Sub jnskTrace _
(ByRef renuType As TraceType, _
ByRef rstrSource As String, _
ByRef rstrMsg As String, _
ByRef rstrUser As String, _
ByRef rstrEXEname As String, _
ByRef rstrIsInTransaction As String, _
ByRef rstrIsSecurityEnabled As String)

(The parameters are ByRef simply for performance reasons.)

Assume that all trace calls are channeled through the stored procedure jnskTraceWrite, then its implementation could look like this when COM Automation is used. (Observe that @@TRANCOUNT is used instead of “yes” or “no” as the value for the “In Tx”-column of the client tool.)

CREATE PROCEDURE jnskTraceWrite
(@vintTraceType INT,
@vstrSource VARCHAR(255),
@vstrMsg VARCHAR(255)) AS
  DECLARE
  @intObj INT,
  @intHr INT,
  @strTran VARCHAR(3),
  @strUser VARCHAR(30)

  --Build the info that is to be sent...
  SET @strTran =
  CAST(@@TRANCOUNT AS VARCHAR(3))
  SET @strUser = SYSTEM_USER

  EXEC @intHr = sp_OACreate
  'jnskTraceSrv.Trace', @intObj OUTPUT
  IF @intHr <> 0 BEGIN
    PRINT 'Problem at creation...'
    RETURN 1
  END

  EXEC @intHr = sp_OAMethod @intObj, 
  'jnskTrace', NULL, @vintTraceType,
  @vstrSource, @vstrMsg,
  @strUser, 'MS SQL', @strTran, ''
  IF @intHr <> 0 BEGIN
    PRINT 'Problem at execution...'
    RETURN 2
  END

  EXEC @intHr = sp_OADestroy @intObj
  IF @intHr <> 0 BEGIN
    PRINT 'Problem at release...'
    RETURN 3
  END

As you see, it’s quite easy to use COM Automation in SQL Server. Even so, you should be careful because you will of course take away resources that SQL Server could have used instead. (In my case I wrote the COM component in VB so there will be a couple of MBs occupied just for this small tool, if it is the only VB thing running on the SQL Server.)

You should also make sure you know that the source code is safe for the COM component. It will run in SQL Server’s address space so it can bring down SQL Server and it can also be used for a hacker attack. Having said that, no one will try out the COM component that I supplied with this part of the article… 😉

In my opinion, COM Automation in SQL Server is much more suitable when you have large granular calls that will take some time to run and which won’t be called frequently because there is quite a lot of overhead associated with the instantiation/destroy mechanism. Sending trace calls doesn’t fit that description at all. A better solution I think is to write an extended stored procedure instead.

IMPLEMENTATION VARIANT TWO: EXTENDED STORED PROCEDURE

SQL Server has support for another thing called ODS, but this time it means Open Data Services and not OutputDebugString. It’s an API that you can use for writing your own external SQL Server resources in, for example, C. There are a lot of extensions included with SQL Server that Microsoft has built as extended stored procedures.

In Visual C++ there is a wizard for creating an extended stored procedure. I’m mostly a VB and SQL guy so I asked my friend Dan Byström if he had an hour or so to help me with writing a couple of extended stored procedures, and xp_jnsktracewrite was one of them.

When I tested another extended stored procedure that we wrote, I found that even if I sent longer strings than 255 characters, the strings were truncated. It took me quite some time to figure out that the wizard for Visual C++ used outdated functionality for receiving parameters. It was also the case that I needed to change the header and lib files for the ODS support that was delivered with Visual C++ 6. It didn’t help to use the files from the latest Platform SDK, but using the samples from SQL Servers own installation CD and the header and lib files from the same place finally made it work. One more thing, I had to export a function that SQL Server 7 and 2000 call to see what version of the header files the extended stored procedure is using. (Search for “Creating Extended Stored Procedures” in Books OnLine (BOL) and read the document with the same title, to get more information about the last comment.)

Anyway, when those problems were solved and the extended stored procedure is installed in the master database, it’s very simple to use the xp from your stored procedures.

CREATE PROCEDURE jnskTraceWrite
(@vintTraceType INT,
@vstrSource VARCHAR(255),
@vstrMsg VARCHAR(255)) AS
  DECLARE
  @strUser VARCHAR(30)

  SET @strUser = SYSTEM_USER

  EXEC master..xp_jnsktracewrite 
  @vintTraceType, @vstrSource, 
  @vstrMsg, @strUser,
  @@TRANCOUNT, ''

Several of the drawbacks of COM Automation apply to extended stored procedures too. I also think it’s harder to build extended stored procedures, but that is highly dependent on your background of course.

On the other hand, extended stored procedures have several advantages, and the most important is that they are faster than COM Automation. Especially when several small calls are needed. I measured a simple stored procedure that only did a single update and had “Begin” and “End” trace calls. When the trace calls were done with my extended stored procedure, I could execute the stored procedure almost twice as many times in a certain time frame as when COM Automation was used instead.

EXAMPLE

Normally I use a standardized code structure for my stored procedures too, but that’s another (long) story and therefore I just show a trace call here, without a complete stored procedure.

SET @strSource = OBJECT_NAME(@@PROCID)
EXEC jnskTraceBegin @strSource

In the sample above you can see that I use OBJECT_NAME() instead of hard coding the name of the stored procedure. Then I send a trace call of the “Begin” type. It’s as simple as that. And of course, when you call jnskTraceBegin, for example, it’s impossible to tell (and you shouldn’t care) what mechanism is really used for sending the trace call. Have I mentioned earlier that I like encapsulation?

START AND STOP TRACING DURING PRODUCTION

I use a registry setting for checking if trace calls should be sent or not from my COM+ components. That registry setting is read at certain time intervals so it does not become such a bottleneck as it would if I had read it before each trace call was done. At first I thought I should read from the registry in my stored procedures too. I could have used xp_regread for reading from the registry so it wouldn’t have been hard, but my guess was that it would slow down the tracing. I couldn’t come up with a really good cache solution for how to store the registry value for my stored procedures for a couple of minutes or so. Instead I decided to let the developer go in directly and comment/uncomment code in the stored procedures such as jnskTraceBegin, jnskTraceEnd and so on, or only in jnskTraceWrite if all calls are made through that one.

I keep an instance of all the stored procedures mentioned above in every database. That way, I can start tracing in just one specific database and not have it started for all the databases of that particular SQL Server instance.

PRE-FILTERING OF TRACE CALLS FOR STORED PROCEDURES

If you let jnskTraceBegin and so on do the trace calls directly, then you have a simple way of filtering, such as only allowing trace calls of a certain type to be done. It will also give you a small performance gain since you skip calling the jnskTraceWrite procedure.

On the other hand, I find it easier to always use jnskTraceWrite so I use this most often. This means I only have one place to add all my pre-filtering, such as only being interested in the trace calls from three specific stored procedures or only being concerned about “Msg” trace calls with a certain variable and so on.

And when you don’t want to have tracing activated, as I said before, you just comment out the code in jnskTraceWrite and optionally in jnskTraceBegin and so on.

OTHER TRACE OPTIONS (FOR TRACING STORED PROCEDURES)

There are several other options for tracing stored procedures and I will briefly discuss some of these below.

• PRINT statements

  I quite often use PRINT statements in jnskTraceWrite or in jnskTraceBegin and so on to get the output directly in SQL Server Query Analyzer instead of in another tool. This is handy when you focus on just the stored procedures. You could use the following in jnskTraceBegin:

    PRINT CAST('Begin' AS CHAR(8)) +
    CAST(@vstrSource AS CHAR(50))

• To do the same thing in jnskTraceWrite, you should use a CASE clause to decide which type of trace call was used. For example @vintTraceType = 2 should be converted to ‘Begin’.
• Another positive effect of using PRINT like this is that you will find the information in ADO’s Errors collection so you can inspect it from there too. (Observe that if you don’t use SET NOCOUNT ON, you will only find the first PRINT statement in the Errors collection if you use SQLOLEDB instead of MSDASQL as the OLE DB driver.)

• SQL Server Profiler

  This is a really powerful tool and you might think that you don’t need a custom tracing solution when you have this. In my opinion I see situations when both are needed. Especially when it comes to projects where stored procedure isn’t the only thing that has been used, but COM+ components too. (Quite common, right?)

  On the other hand, it should be possible to use calls to sp_trace_generateevent with user-configured events from jnskTraceWrite to use SQL Server Profiler as the client tool for the tracing. SQL Server Profiler is of course a much better and more capable client tool than my quick hack jnskTraceView. To take this to the extreme, jnskTraceWrite could be called from ASP and the COM+ components too, to collect all trace information in SQL Server Profiler. My guess is that this isn’t a good solution since it probably adds a lot of overhead to the system, but I haven’t tried it.

• Save trace calls to a table in SQL Server

  The drawback is probably the same as with calling sp_trace_generateevent from everywhere (I mean from ASP and COM+ components too). There will be too much effect on the system and it’s important to have as little as possible of that.

• T-SQL Debugger

  In SQL Server 2000, a T-SQL Debugger is integrated with SQL Server Query Analyzer. This works like a charm. But once again, you need different types of tools for different problems and in different phases of the project.

  BOL tells us that we should take care not to use the T-SQL debugger on a production server. The debugger can lock certain resources.

• Write to a file

  I will discuss this further in the following parts of this article.

• Writing to Visual Studio Analyzer (VSA)

  Finally, it’s possible to write messages to VSA, but I decided a year ago to skip that at that time and I haven’t changed my mind yet. If you ask around you will probably find that very few people are using VSA as of today. Perhaps it will change with the next version.

OTHER TOOLS

Yes, I know that I’m definitely not inventing the concept of tracing. It’s discussed in several books and you will find solutions for it in several third-party products (as well as in the .NET Framework, as I mentioned earlier) and so on. Once again, I’d just like to stress the need for it, not my particular solution. (As you can see I’m doing my best to be a really nagging parent to my three-year-old son. Some of that is spilling over to my articles…)

SHORTCOMINGS WITH THIS PROPOSAL

It’s time for a couple of confessions. (I will add some more in the following articles.)

• Problem with collecting output from several machines

  This is possible since the client tool can save the collected information to a file. Several of those files can then be opened from one instance of the client tool and the files will be merged. The problem with this is the synchronization of the clocks of all the machines. I will discuss this further and present a solution in the third part of the article.

  Another easy solution would be if I (or someone else) added an implementation variant so that I can request the output to be sent to a certain file on a shared drive instead of as calls to OutputDebugString. There are several things that should be done, but we must make money too, right?

• Not possible to view trace output remotely

  See the bullet above.

  You should also take a look at DebugView from Sysinternals, see http://www.sysinternals.com/dbgview.htm. This tool allows you to collect ODS calls from a remote machine.

• Overhead is definitely not zero

  Especially not when trace calls are activated and you are in listen mode. When you have deactivated trace calls, the overhead is quite low. I will present some diagrams for that in a later part of the article.

  The important thing to remember is to use trace calls in a smart manner. Don’t put them in a tight loop for example, if it’s not really important.

• Not really usable from User-Defined Functions (UDF)

  In the current implementation of UDFs in SQL Server 2000, you can’t call stored procedures. You can call extended stored procedures so it’s possible to use my trace solution, but you get some trouble with the configurational aspects. I guess I could create two versions of the xp_jnsktracewrite, one empty and one that does the trace call. Then it’s possible to register the correct one depending on whether tracing should be activated or not, but now it starts to get messy. There are just too many places to change to start tracing and since the extended stored procedure is for the whole system, it won’t be possible to decide to use tracing for some databases and not to use it for others.

  UDFs are really cool, but they also have some rough edges in this first version that I hope will get fixed later.

• Especially for SQL Server and not Oracle, DB2 and so on

  As I understand it, both extended stored procedures and COM Automation don’t work with Oracle, DB2 and so on, so the discussed mechanisms here are proprietary. On the other hand, I guess it should be easy to write a similar tool to use from, for example, Oracle that can call OutputDebugString.

SUPPLEMENTAL FILES

There won’t be any source code today for the client tool and the COM component, but the reason for that is that I will upgrade both those for the second and third part of the article. You will find the tools mentioned in this part of the article so you can try them, and you will find the source code for the extended stored procedure.

Please observe that all use of the supplied tools is at your own risk. They were written very quickly and are given away as tools for inspirational purposes only. There will probably be upgraded versions of all the tools supplied with parts two and three of the article.

The tools have been tested with:

• SQL Server 7 / Windows NT 4
• SQL Server 2000 / Windows 2000

Client tool:

• jnskTraceView.exe
  Requires that you have the VB6 environment or a VB6 created app installed on the system before. Uses Microsoft Common Dialog Control 6.0 and Microsoft Windows Common Controls 6.0.

• jnskTrVw.ocx
  Register with regsvr32.

Stored procedure support:

• jnskTrace.sql
  Execute this script in SQL Query Analyzer to get the stored procedures added to the current database.

• xp_jnsktracewrite.dll
  Register in the master database with:
  sp_addextendedproc
  ‘xp_jnsktracewrite’,
  ‘{your path}xp_jnsktracewrite.dll’
• xp_jnsktracewrite.zip
  The code for the xp.

COM component:

• jnskTraceSrv.dll
  Register with regsvr32 (requires that you have the VB6 environment or a VB6 created app installed on the system before).

SUMMARY

Hopefully I have inspired you to start using tracing in your applications. And not only in your ASP code and COM+ components, but also in your stored procedures. I’ve been working with stored procedures in SQL Server since 1995 and since then I have grown more and more eager to use them! With this comes a greater need for the same debuggability support I want to have in my other components.

Perhaps some of you think that there was too much talk about SQL Server and stored procedures and too little about COM+ in this part of the article? My guess is that at least 75% of the developers of configured COM+ components in the world are also using SQL Server. And for the other 25% percent, I will talk much more about COM+ in the second part of this article. Expect the second part of the article, but don’t hold your breath. 😉

Special thanks to Dan Byström at Visual Design!