Testing with Profiler Custom Events and Database Snapshots

By Mike Femenella on 22 June 2009 | Tags: Stored Procedures , Profiler & Trace

We've all had them. One of those stored procedures that is huge and contains complex business logic which may or may not be executed. These procedures make it an absolute nightmare when it comes to debugging problems because they're so complex and have so many logic offshoots that it's very easy to get lost when you're trying to determine the path that the procedure code took when it ran. Fortunately Profiler lets you define custom events that you can raise in your code and capture in a trace so you get a better window into the sub events occurring in your code. I found it very useful to use custom events and a database snapshot to debug some code recently and we'll explore both in this article. I find raising these events and running Profiler to be very useful for testing my stored procedures on my own as well as when my code is going through official testing and user acceptance. It's a simple approach and a great way to catch any performance problems or logic errors.

Setting Up AdventureWorks

We will make a snapshot of the AdventureWorks 2008 sample database. All the code in this article is based on SQL Server 2008.  You will need to modify the updates we use later in our stored procedure to make it compatible with 2005. You can find all of the AdventureWorks sample databases on Microsoft's CodePlex site. Assuming you have Adventureworks installed, open up query analyzer and let's get started by creating a snapshot of Adventureworks.

--Create a snapshot before we add any code
CREATE DATABASE AdventureWorks_PreTestSnapshot ON
( NAME = AdventureWorks_Data, FILENAME = 
'C:\AdventureWorks_data_1800.ss' )
AS SNAPSHOT OF AdventureWorks;
GO

Simple enough here. We're creating a snapshot of the database on our C drive and we're calling it AdventureWorks_PreTestSnapshot. This will give us a Simple enough here. We're creating a snapshot of the database on our C drive and calling it AdventureWorks_PreTestSnapshot. This will give us a read-only copy of AdventureWorks and take up very little space on our drive. Snapshots use copy on write, which means when a page is updated in the primary database, in this case AdventureWorks, the old page is written to the snapshot database so your copy remains an exact image of your data at the time the snapshot was taken.

We'll be working with the Sales.Customer table so let's do a quick check and verify that we have no records that have been modified in the last day. You should have 0 rows returned.ored procedure that we can use to simulate a procedure with complex logic. Your real world procedures will of course be much more complex than this but for the purposes of this article we'll keep it fairly simple:

use AdventureWorks
GO
1 Create procedure pManyOptions
2 as

3 --Make sure a snapshot exists for the current database before testing
4 if not exists(select * from sys.databases 
             where source_database_id =DB_ID() 
             and snapshot_isolation_state=1 and is_read_only=1)
5 begin
6 RAISERROR('No snapshot exists for the current database' ,16,1)
7 RETURN
8 END

9 declare @message nvarchar(100)


10 Update top(5) Sales.Customer set ModifiedDate =GETDATE()
11 set @message='Update occured: ' + convert(varchar(30),GETDATE(),120)
12 EXEC sp_trace_generateevent @eventid=82, @userinfo=@message

13 WAITFOR DELAY '00:00:10';

14 set @message='Wait for occured: ' + convert(varchar(30),GETDATE(),120)
15 EXEC sp_trace_generateevent @eventid=83, @userinfo=@message

16 GO

Let's take a closer look at the code. First (Line 4) we're making sure that our test can't run if there isn't a snapshot. We're doing this to keep from shooting ourselves in the foot. It's a real drag to step on your test scenario and have to reset it later when you want to run it again. The snapshot, as you'll see later helps us avoid this problem. Next (Lines 10 & 11) we update top 5 records in the Sales.Customer table with today's date and then set a message variable that we'll use for our custom event. Finally we get to the good stuff in line 12, we raise a custom event that profiler will pick up. Profiler defines 10 user configurable events defined as User Configurable:0 through User Configurable:9. These events correspond with eventid's 82-91 so for example if you raised eventid 82 in your procedure you would use the user configurable event 0 in your profiler trace. We'll get to that in more detail in a little bit. We then put a waitfor delay in line 13 so we can see a time span other than a few milliseconds between our sp_trace_generateevent on line 12 and line 15. Now let's change applications and take a look at setting up a trace in profiler to capture the generate event calls on line 12 and 15. Open up Profiler and select File>>New Trace and connect to your database instance. Click on the events selection tab and click on the checkbox for “All Events”. Scroll all the way down your list of events and expand “User Configurable”. Since we're raising events 82 and 83 in our stored procedure you should check the box to the left of UserConfigurable:0 and UserConfigurable:1 to add them to your trace. You can add or remove other events as you see fit. When you're ready, go ahead and click the “RUN” button to start your trace.

Now we want to run some code in query analyzer to test out our user configurable events. Execute the code below to run the stored procedure we created earlier.

--Generate code to call our test procedure
exec pManyOptions

When the code has completed running you should see something similar to this in your profiler results. Notice you now have 2 events that profiler was able to capture but did not throw errors in query analyzer when your code was executing. For complex procedures with variations in how they execute this is a real boon in debugging.

Now that we have run our test let's take a look at resetting the database to wipe out what we did. This is useful scenarios where we've changed code and need to execute a retest. First we can see that we now have 5 updated rows in the AdventureWorks database.

--Counts Before Running our Procedure
use AdventureWorks
GO
select COUNT(*) from Sales.Customer where ModifiedDate between GETDATE()-1 and GETDATE()

We want to recover the Adventureworks database by restoring it from our snapshot. To do this we execute the following:

USE master  
RESTORE DATABASE AdventureWorks FROM DATABASE_SNAPSHOT = 'AdventureWorks_PreTestSnapshot';
GO

Now we can verify that our AdventureWorks database has been reset and we're ready for another round of testing. We should now see 0 rows changed since we restored our clean copy.

use AdventureWorks
GO
select COUNT(*) from Sales.Customer where ModifiedDate between GETDATE()-1 and GETDATE()

Finally here is the code for you to cleanup the snapshot you created when you're done with testing.

Drop Database AdventureWorks_PreTestSnapshot

I hope this article helps you simplify some of your debugging and testing drudgery and makes it a little bit easier next time you have to dig under the covers of some of your more complex procedures.