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

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.

Answer 2

Maybe you can use SQL CLR to do the tracing as described here How to log in T-SQL

Answer 3

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 4

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 5

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

Answer 6

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).