Debugging (Nested) Stored Procedures with SQL Server Profiler

bird nest with white egg

Nested stored procedures (or stored procedures that call other stored procedures) are a mixed blessing and a curse. They also serve as powerful fodder for starting holy wars. On the one hand, they serve as a great means for allowing developers to re-use code and thereby avoid DRY. On the other hand, they can also cause performance problems given that the very ability to re-use code implies that code can (and will—eventually) be used in ways that the original designers might not ever have anticipated. That, and they can be tricky to debug—because if a 'parent' stored procedure might potentially make a call to one or more ‘child’ (or nested) stored procedures, then it can be hard to get a sense for what’s going on 'internally'—or within that child procedure.

Related: SQL Server's Trace and Replay Tool

Debugging Options Other than SQL Server Profiler

One obvious option that should come to mind for debugging complex sprocs would be built-in debugging functionality. I personally haven't used that capability on or with or against any SQL Server in over a decade. I've just had too many bad experiences jumping through hoop after hoop trying to get that set up in a distributed environment in the past – to the point where I honestly won't even bother trying anymore.

That, and debugging just isn't EVER an option in a production setting. Ever.

Extended Events are also an option for trying to do more or less what I'm outlining here—but that's another blog post. As such, this post deals with some tricks you can use with SQL Server Profiler.

Using SQL Server Profiler’s Ability to Peek into Sproc Execution Details

Out of the box, a default SQL Server Profiler trace typically just looks at batch and RPC level events. But there's a whole category of SP (Stored Procedure) events that can be used to peak in on the actual 'goings on' inside of a sproc when it is run – including when it makes calls to other sprocs (or, more specifically: there's enough detail provided that you can SEE when 'child' sprocs are called).

So, with the following Events specified:

And with the following code:

IF OBJECT_ID('dbo.ChildSproc','P') IS NOT NULL
        DROP PROC dbo.ChildSproc
GO

CREATE PROC dbo.ChildSproc
        @input nvarchar(40)
AS
        SET NOCOUNT ON;

        SELECT @input [output];

        RETURN 0;
GO


IF OBJECT_ID('dbo.ParentSproc','P') IS NOT NULL
        DROP PROC dbo.ParentSproc;
GO

CREATE PROC dbo.ParentSproc
        @input nvarchar(20)
AS
        SET NOCOUNT ON;

        IF LEN(@input) < 10
                EXEC ChildSproc 'First Option Executed';
        ELSE
                EXEC ChildSproc 'Second Option Executed';  

        DECLARE @someParam nvarchar(40);
        SET @someParam = @input + ' (more text here)';

        EXEC dbo.ChildSproc @someParam;

        RETURN 0;
GO

If I execute the following:

EXEC Parent'Text';

Then I’ll end up with the following:

And note that I’ve highlighted how you won’t actually get to see what the value of @someParam is—because ChildSproc is, in this case, being called with a parameter as input. Note, in contrast, however, that about 4-5 lines up, you DO see exactly what's being passed into ChildSproc—because it’s being called with data instead of data 'in-lined' into parameters.

Some Words of Caution

Of course, just as you wouldn’t want to EVER debug code out in production (as doing so can/will serialize all execution through your paused debugging thread), there are some inherent risks with turning on SP:StmtStarted/Completed as well—in that these events provide a statement-by-statement view into everything that's executing within a sproc on your server. As such, IF you NEED to 'debug' out in production by using Profiler in the fashion outlined above, I’d recommend the following:

  • To Not To. Again, debugging should be done on a dev/staging/test server whenever possible. Make sure you have no other options before turning on an aggressive Profiler trace out in production. (And another, less expensive, option would be Extended Events.) And, while it's POSSIBLE to do this with a decent set of filters, it's a bad idea to get 'comfortable' debugging in prod in many cases because while operation might not cause problems, there's no telling what the 2nd operation or 20th might do if you're not being cautious.
  • Use Suitable Filters. Causing the server to spit out details about EVERY statement being executed in EVERY sproc can quickly generate an absurd™ amount of data. So, if you're targeting just a problematic sproc or two, then drop their OBJECT_IDs into the Column Filters for profiler. So, for example, by querying SELECT OBJECT_ID('ParentSproc') and then doing the same for ChildSproc, I was able to obtain the Object_ids for both of these sprocs, and then dropped them into the appropriate Column Filter as shown below: Edit Filter

Which, in turn, constrains statement output and details to JUST statement-level details coming out of either of these sprocs.

Otherwise, the ability to 'peer' into the actual 'goings on' within an executing stored procedure via SQL Server Profiler is a decent 'trick' that you can use in SOME cases to help debug complex dependency chains and calls that might show up in some of your sprocs.

Discuss this Blog Entry 2

on Jun 28, 2013

One very handy filtering trick when tracing T-SQL server code with Profiler, is filtering on objectname which applies to the name of the stored proc / function or trigger.. I use a "Not like" filter to exclude nested server code not relevant to the code I want to look for. It makes the trace a lot smaller and much more readable.

on Jun 28, 2013

Appreciate the tip! Thank you.

Please or Register to post comments.

What's Practical SQL Server?

Practical advice, insight, and help for core SQL Server considerations.

Contributors

Michael K. Campbell

Michael K. Campbell is a contributing editor for SQL Server Pro and Dev Pro and is an ASPInsider. Michael is the president of OverAchiever Productions, a consultancy dedicated to technical evangelism...
Blog Archive

Sponsored Introduction Continue on to (or wait seconds) ×