Recording Debugging Information Inside a SQL Server Function Call

This is a tip that I originally posted on 𝕏. There was more interest than I expected, so I am expanding on it here.

Function Debugging

T-SQL functions come with many restrictions, which can make them tricky to debug during development.

Without an SSMS T-SQL debugger, many procedure authors depend on PRINT and RAISERROR messages to trace execution flow and report local variable values.

Neither of these statements is allowed in the body of a T-SQL function, though only RAISERROR is explicitly documented to be unsupported.

For example:

DROP FUNCTION IF EXISTS dbo.F;
GO
CREATE FUNCTION dbo.F ()
RETURNS bigint
WITH SCHEMABINDING
AS
BEGIN
    PRINT 'Debug message';
    RETURN CONVERT(bigint, 0);
END;

Attempting to create that function fails with an error message:

Msg 443, Level 16, State 14, Procedure F, Line 1 [Batch Start Line 1]
Invalid use of a side-effecting operator 'PRINT' within a function.

A very similar error message is produced if you try to use RAISERROR instead.

Side effects

The meaning of “a side-effecting operator” in that error message is not exactly clear.

There is a general statement:

The statements in a BEGIN...END block can’t have any side effects.

Function side effects are any permanent changes to the state of a resource that has a scope outside the function such as a modification to a database table.

The only changes that statements in the function can make, are changes to objects local to the function, such as local cursors or variables.

Modifications to database tables, operations on cursors that aren’t local to the function, sending e-mail, attempting a catalog modification, and generating a result set that is returned to the user are examples of actions that can’t be performed in a function.

and elsewhere:

Side effects are changes to a global state of the database, such as an update to a table, or to an external resource, such as a file or the network; for example, modifying a file or sending an e-mail message.

None of that explains why PRINT and RAISERROR are considered ‘side-effecting’, but that does not change the reality.

Allowed statements

Another documentation page lists the allowed statements in a function:

• Assignment statements.
• Control-of-Flow statements except TRY...CATCH statements.
• DECLARE statements defining local data variables and local cursors.
• SELECT statements that contain select lists with expressions that assign values to local variables.
• Cursor operations referencing local cursors that are declared, opened, closed, and deallocated in the function. Only FETCH statements that assign values to local variables using the INTO clause are allowed; FETCH statements that return data to the client aren’t allowed.
• INSERT, UPDATE, and DELETE statements modifying local table variables.
• EXECUTE statements calling extended stored procedures.

Despite saying extended stored procedures can be called without qualification, in practice only certain ones are allowed. If you try to call one of the others within a function, you’ll receive error 557:

Msg 557, Level 16, State 2, Line 1
Only functions and some extended stored procedures can be executed from within a function.

Curiously, xp_cmdshell is allowed and it is hard to think of one with more potential for side-effects on a database.

The Workaround

For users of SQL Server 2016 and later, we can use the system extended stored procedure sp_set_session_context to save sql_variant values up to 8000 bytes in one or more session context entries, each with its own descriptive key.

Once the function call is complete, we can retrieve the saved value(s) by calling SESSION_CONTEXT with the key.

Example

I wanted to record some information from within a user-defined function when I was working on my article, Accessing a SQL Server Table Variable in a Different Scope. The demo didn’t make it into the final publication, but it’ll do as an example here.

The idea was to collect supporting evidence for the statement that table-valued parameters (TVPs) are passed to a function by reference, avoiding a copy of the input data set:

1. Populate the table variable with enough rows to take a reasonable length of time.
2. Record the time we called the function (outside the function).
3. Record the time the function started (inside the function).
4. Show that the time between steps 2 and 3 was too short to involve a full copy of the table variable into the TVP (passing by value).

First, we will need a persistent type for the TVP:

DROP TYPE IF EXISTS dbo.TVP;
GO
CREATE TYPE dbo.TVP AS table 
(
    i integer NOT NULL
);
GO

The function simply counts the number of rows in the TVP.

It uses sp_set_session_context to record the start time of the function body’s execution:

DROP FUNCTION IF EXISTS dbo.CountRows;
GO
CREATE OR ALTER FUNCTION dbo.CountRows 
(
    @TVP AS dbo.TVP READONLY
)
RETURNS bigint 
-- TVPs disallow inlining anyway
WITH INLINE = OFF
AS
BEGIN
    -- Get the function start time
    DECLARE @Start sql_variant = 
        CONVERT(sql_variant, SYSUTCDATETIME());
    
    -- Save the start time debug info using session context
    EXECUTE sys.sp_set_session_context 
        @key = N'dbo.CountRows StartTime',
        @value = @Start,
        @read_only = 0;

    -- Return the result
    RETURN 
    (
        SELECT COUNT_BIG(*) 
        FROM @TVP
    );
END;
GO

The demo itself inserts 5 million rows into a table variable, then passes that into the function as a TVP for counting. It records the time of the call to the function, to identify any delay in copying the table variable into the TVP:

DECLARE @TVP AS dbo.TVP;

-- Add 5 million rows
INSERT @TVP 
    (i) 
SELECT TOP (5 * 1000 * 1000) 
    CONVERT(integer, CRYPT_GEN_RANDOM(4))
FROM sys.all_columns AS AC1
CROSS JOIN sys.all_columns AS AC2;

DECLARE 
    @CallStart datetime2 = SYSUTCDATETIME();

-- Table variable passed by reference
-- The 5 million rows are *not* copied
SELECT 
    NumRows = dbo.CountRows(@TVP);

-- Retrieve the function's start time from session context
DECLARE
    @FunctionStart datetime2 = 
        CONVERT
        (
            datetime2, 
            SESSION_CONTEXT(N'dbo.CountRows StartTime')
        );

-- Free the session context
-- (to allow SQL Server to release the memory)
EXECUTE sys.sp_set_session_context 
    @key = N'dbo.CountRows StartTime', 
    @value = NULL;

-- Show time delay
SELECT 
    [Elapsed μs] =
        DATEDIFF
        (
            MICROSECOND, 
            @CallStart,
            @FunctionStart
        );
GO

Result

As expected, there is a minimal delay because the table is passed by reference—there is no data copy.

The test as a whole runs for almost 7 seconds because it takes a while to insert 5 million rows at the start:

Execution plan showing that loading the table variable takes over 6s

The reported timing difference is typically reported as 0μs, which says more about the resolution of the timer used than anything else. Still, it is clear the initial data load takes much longer than passing the table variable as a TVP. It is clearly passed by reference and not by value.

Summary

The demo itself isn’t important here; the point is to show that diagnostic data can be saved inside a function call using the sp_set_session_context extended stored procedure, and retrieved using SESSION_CONTEXT.

This method can be adapted to record any diagnostic data, not just timing. Each item will require a separate sp_set_session_context call and a unique key.

For an example, see this online db<>fiddle demo—a variation of Erik Darling’s Simulating WAITFOR In Scalar UDFs with extra debugging information added.

There is a 1 MB limit per session, so use it judiciously and be sure to clean up afterwards by setting the context key’s value to NULL.

One restriction to be aware of is that a scalar function calling an extended stored procedure is not eligible for scalar UDF inlining, which was introduced in SQL Server 2019. Function inlining can result in dramatic performance improvements.

If you do use this technique when developing T-SQL functions, ensure you remove the session context calls once development is complete.

Thanks for reading.