How to trace T-SQL function calls

Question

I'm trying to debug a rather complicated formula evaluator written in T-SQL UDFs (don't ask) that recursively (but indirectly through an intermediate function) calls itself, blah, blah.

And, of course, we have a bug.

Now, using PRINT statements (that can then be read from ADO.NET by implementing a handler for the InfoMessage event), I can simulate a trace for stored procedures.

Doing the same for UDF results in a compile time message:

Invalid use of side-effecting or time-dependent operator in 'PRINT' within a function.

I get the message (PRINT does some stuff like resetting @@ROWCOUNT which definitly is a no-no in UDFs, but how can I trace through the calls? I want to have this trace printed out, so I can study it without getting distracted by stepping through the calls in the debugger...

EDIT: I have tried to use the SQL Profiler (this was a first time one for me), but I can't figure out what to trace for: Although I can get the trace to output the queries sent to the database, they are opaque in the sense that I can't drill down to the Expression-UDFs called: I can trace the actual Stored Procedure invoked, but the UDFs called by this procedure are not listed. Am I missing something? I guess not...

EDIT #2: Allthough the (auto-)accepted answer does trace the function calls - very helpful, thanks - it does not help in finding out what parameters were passed to the function. This, of course, is essential in debugging recursive functions. I will post if I find any sollution at all...

Answer 1

If it was me, I'd create a table with one column (varchar(1000) maybe?) and perform inserts to that table. You could add date/time columns too if you like, but the main point is you can then query that table as if it were a log file.

Of course, how to then go through removing those calls for the "production" code is left as an exercise for the reader :p

Answer 2

Why not use SQL Profiler with statement level events added?

Edit: Add events for Stored Procedures : SP:Stmt Starting or SP:Stmt Completed Use variables to debug if needed, i.e. set @debug='i am here'; UDF's, while not technically stored procedures, will get traced with the statement level events.

Answer 3

I second the SQL Profiler suggestion. Take some time to set it up so that only the events you are interested in are logged to cut output size. You can output the trace to a file - I have frequently then loaded that file back into a table to enable analysis. (extremely handy for performance analysis, though no doubt someone will tell me that 2008 has this all built in somwehere...)

Sometimes you won't have permissions to run SQL Profiler as it does slow the server down - ask your DBA to grant you permission on your Dev server. They shouldn't have any problems with that.

Answer 4

Use SQL Profiler, I recommend you go overboard on adding events the first time around which will let you get a feel for what you need. Without testing I would add the events for SP:StmtStarted (or Completed or both), SQL:StmtStarted (again Completed or Both).

Answer 5

Well in the past I have had to take typical values that would be in the UDF and then run just the udf part in a separate query window as straight SQL not a udf using the typical values as variables set with a declare and a set statement. If it is run from a table instead of having only one value, I would set up a temp table or table variable with the input values and then run them through the sql in the UDF (but again as straight SQL not a UDF) through a cursor. By running straight SQL you could have print statements in it to see what is happening. I know this is a pain, but it works. (I go through a simliar process when creating/debugging triggers, setup #inserted and #deleted with my test values and then test the code I intend to put into the trigger, then global replace the # with nothing and add the create trigger code.)

Answer 6

Maybe you can use SQL CLR to do the tracing as described here http://stackoverflow.com/questions/58709/how-to-log-in-t-sql

Answer 7

This looks like what you need but it's only available in team/pro versions of Visual Studio.

Answer 8

If you have Visual Studio there might be a way you can use that to step into the UDF by calling your UDF via a stored procedure.

In visual studio...

• Create a blank project
• Open Server Explorer
• Connect to your SQL Server in Server Explorer
• Naviagate and double click on the stored procedure which calls the UDF
• Set a breakpoint in your stored procedure.
• Then right click and select Step Into Stored Procedure (or via the Data menu).

Here is Microsoft link on it.

Walkthrough: Debugging a T-SQL User-Defined Function (UDF) http://msdn.microsoft.com/en-us/library/ms165047(VS.80).aspx

How to: Step into an Object Using Server Explorer http://msdn.microsoft.com/en-us/library/ms165041(VS.80).aspx

Apologies if you dont have Visual Studio.

Answer 9

Can you take your function, and make a second copy of it, but returning a table type with an additional column for your debug information.

For example, the mySum function below

CREATE FUNCTION mySum
(   
    @param1 int,
    @param2 int
)
RETURNS INT AS
BEGIN
    DECLARE @mySum int

    SET @mySum = @param1

    SET @mySum = @mySum + @param2

    RETURN @mySum

END
GO
SELECT dbo.mySum(1, 2)

Would turn into

CREATE FUNCTION mySumDebug
(   
    @param1 int,
    @param2 int
)
RETURNS @myTable TABLE
(
    [mySum] int,
    [debug] nvarchar(max)
)
AS
BEGIN
    DECLARE @debug nvarchar(max)

    SET @debug = 'Declare @mySum variable. '
    DECLARE @mySum int

    SET @debug = @debug + 'Set @mySum = @param1(' + CONVERT(nvarchar(50), @param1) + ') '
    SET @mySum = @param1


    SET @debug = @debug + 'Add @param2(' + CONVERT(nvarchar(50), @param2) + ') to @mySum(' + CONVERT(nvarchar(50), @mySum) + ') '
    SET @mySum = @mySum + @param2

    SET @debug = @debug + 'Return @mySum variable. '

    INSERT @myTable (mySum, debug) VALUES (@mySum, @debug)

    RETURN
END
GO
SELECT mySum, debug FROM dbo.mySumDebug(1, 2)

Not an ideal solution, but useful just to return some text to help track down a bug.

Answer 10

In the SQL profiler, you need: SP:Starting, SP:StmtStarting, SP:Completed, SQL:BatchStarting. Then, you get every entry, exit from the functions/stored procedures.

alter FUNCTION [dbo].[ufn_mjf](@i numeric(10))
    RETURNS numeric(20) 
AS
BEGIN
declare @datapoint varchar(10)

    set @datapoint = 'hello world'

    return @i
END
go
drop table foo
go
create table dbo.foo ( foo_id numeric(10)) 
go
delete from foo
insert into foo ( foo_id ) values ( 1 )
insert into foo ( foo_id ) values ( 2 )

select foo_id, dbo.ufn_mjf(foo_id) from foo

with this, I get:

SQL:BatchStarting   alter FUNCTION [dbo].[ufn_mjf](@i numeric(10))
SQL:BatchStarting   drop table foo
SQL:BatchStarting   create table dbo.foo ( foo_id numeric(10)) 
SQL:BatchStarting   delete from foo
    insert into foo ( foo_id ) values ( 1 )
    insert into foo ( foo_id ) values ( 2 )
    select foo_id, dbo.ufn_mjf(foo_id) from foo
SP:Starting select foo_id, dbo.ufn_mjf(foo_id) from foo
SP:StmtStarting set @datapoint = 'hello world'
SP:StmtStarting return @i
SP:Completed    select foo_id, dbo.ufn_mjf(foo_id) from foo
SP:Starting select foo_id, dbo.ufn_mjf(foo_id) from foo
SP:StmtStarting set @datapoint = 'hello world'
SP:StmtStarting return @i
SP:Completed    select foo_id, dbo.ufn_mjf(foo_id) from foo

is that enough for you?

Answer 11

I use SQL SPY which does what you are looking for and more.

SQL SPY

SQL SPY Feature Documentation

SQL SPY's Incoming SQL Sniffer shows the incoming SQL code of each connection (Includes DDL and DML statement tracking)

This feature is designed for MS SQL Server 2005\2008, but will work with MS SQL Server 2000 in limited scope. It has the ability to record and report on Incoming SQL. How to use the features: See

Disclosure: I am part of the SQL SPY team.