Tracking Dynamic SQL performance automatically with a wrapper on sp_executesql (Dynamic SQL Inception)

in some projects I have a lot of Dynamic SQL going on, some queries are fast, some queries are slow, it depends on how the dynamic statement is actually put together ¯\_(ツ)_/¯ Tracking the performance of such statements is usually difficult because you don’t really know “why it’s slow” and you have to interpolate data from the app and the plan cache (if the plan is still there and wasn’t purged due to memory pressure) and try to figure out which was the piece of the offending dynamic SQL and why it did that.

Inspired by this post by Eric Darling, last year I pushed the idea to an “maybe I can use this” level, by writing a wrapper around sp_executesql that allows me to automatically track the duration and code of each Dynamic SQL Statement without any major code change to an existing script* My idea was to have a wrapper around sp_executesql in order not to change the existing syntax but only the SP to actually execute. I’ve succeeded in part to do so.

Less words, more code, let’s see what’s up, I’ll be creating the table where I’ll log the information first:

SET ANSI_NULLS ON
GO

SET QUOTED_IDENTIFIER ON
GO

DROP TABLE IF EXISTS [dbo].[DYNSQL_LOG]

CREATE TABLE [dbo].[DYNSQL_LOG](
  [Id] [bigint] IDENTITY(1,1) NOT NULL,
  [UserName] [nvarchar](128),
  [StartTime] [datetime2](7),
  [EndTime] [datetime2](7) NULL,
  [RunTimeSeconds]  AS (datediff(second,[StartTime],[EndTime])) PERSISTED,
  [RunTimeMilliSeconds]  AS (datediff(millisecond,[StartTime],[EndTime])) PERSISTED,
  [DynamicSQL] [nvarchar](max),
  [Failed] [bit] NULL,
  [ErrorMsg] [nvarchar] (256) NULL,
  [Tag] [varchar] (512) NULL
 CONSTRAINT [PK_DYNSQL_LOG] PRIMARY KEY CLUSTERED 
(
  [Id] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = OFF) ON [PRIMARY]
) ON [PRIMARY]
GO

I added two persisted columns to show me the Runtime of the query in seconds and Milliseconds, that may be an overkill, but extra parts are easy to remove. As you see I’ve added a column to track any errors and error message, in case some statements go bad; The [Tag] column was a late addition that I found useful as a bookmark to remember where those statements came from, in order to be able to filter on it later (e.g. by the caller store procedure name or whatever tag it’s useful for you), it’s not a mandatory parameter regardless.

Now take a break, here it comes the code, I’ll explain everything later, stay calm:

CREATE OR ALTER PROCEDURE [dbo].[ExecuteAndTrackSQL] (
    @USER_IDEN NVARCHAR(256) = 'Undef',
    @SQL NVARCHAR(MAX),
    @PARAM_VALUES SQLParameters READONLY,
    @RETURN nvarchar(max) = NULL OUTPUT,
    @SKIP_ERRORS bit = 0,
    @TAG varchar (512) = NULL
    )
AS
--09/01/2017 Emanuele Meazzo
--Added @TAG to Tag Code to know from where it was launched (or other tagging)
--14/08/2017 Emanuele Meazzo
--Added error tracking information
--Logging full execution stack for parameter launch
--07/07/2017 Emanuele Meazzo
--Added generic parameter output (limited to 1 in this release)
--31/05/2017 Emanuele Meazzo
--First Release
BEGIN

SET NOCOUNT ON;

SELECT @USER_IDEN = SUSER_NAME()
WHERE @USER_IDEN = 'Undef'

--Log the Start
INSERT INTO dbo.DYNSQL_LOG (UserName, StartTime, EndTime, DynamicSQL, Tag)
    VALUES (@USER_IDEN, SYSDATETIME(), NULL, @SQL, @TAG)

DECLARE @ID int = SCOPE_IDENTITY();

DECLARE @Count int
SELECT @Count = COUNT(*)
FROM @PARAM_VALUES;

IF(@Count = 0)
BEGIN
    --Execute without parameters
    BEGIN TRY

     EXEC sp_executesql @SQL;
    END TRY
    BEGIN CATCH
     UPDATE dbo.DYNSQL_LOG
     SET EndTime = SYSDATETIME(),
      Failed = 1,
      ErrorMsg = LEFT(ERROR_MESSAGE(),256)
     WHERE
    Id = @ID;

     IF(@SKIP_ERRORS = 0)
      THROW

    END CATCH;
END
ELSE
BEGIN
     SET @SQL = REPLACE(@SQL,'''',''''''); --Escape ' for execution
     --Execute with parameters (max 1 Output parameter)
     DECLARE @SupportSQL_Header		nvarchar(max)
     DECLARE @SupportSQL_Footer		nvarchar(max)
     DECLARE @SupportSQL_Parameters	nvarchar(max)

     SELECT @SupportSQL_Header = COALESCE(@SupportSQL_Header,N'SET NOCOUNT ON;' + CHAR(13)+CHAR(10)) + 'DECLARE @' + P.Name + N' as ' + REPLACE(P.Type,'OUTPUT','') + ' = ' +
     CASE
      WHEN P.Type LIKE 'varchar%' THEN '''' + P.Value + ''''
      WHEN P.Type LIKE 'nvarchar%' THEN 'N''' + P.Value + ''''
      ELSE CONVERT(nvarchar(40),P.Value)
      END
     --+ CHAR(13)+CHAR(10)
     FROM @PARAM_VALUES P

     SELECT @SupportSQL_Parameters = COALESCE(@SupportSQL_Parameters,'DECLARE @Parameters nvarchar(max) = N''') + N'@' + P.Name + N' as ' + P.Type + N', '
     FROM @PARAM_VALUES P

     SET @SupportSQL_Parameters = LEFT(@SupportSQL_Parameters,LEN(@SupportSQL_Parameters)-1) + N''''

     SELECT @SupportSQL_Footer = COALESCE(@SupportSQL_Footer,N'EXEC sp_executesql @SQL, @Parameters, ') + '@' + P.Name + N' = @' + P.Name +N', '
     FROM @PARAM_VALUES P

     SET @SupportSQL_Footer = LEFT(@SupportSQL_Footer,LEN(@SupportSQL_Footer)-1)

     --Find the eventual output variable
     DECLARE @OUT_VARIABLE nvarchar(256)
     SELECT TOP 1 @OUT_VARIABLE = Name
     FROM @PARAM_VALUES
     WHERE Type LIKE '%OUTPUT%'

     --Adds 'OUTPUT' in the parameter assign step if there is an output variable in the parameters
     IF @OUT_VARIABLE IS NOT NULL
      SET @SupportSQL_Footer = REPLACE(@SupportSQL_Footer,N' = @' + @OUT_VARIABLE,N' = @' + @OUT_VARIABLE + N' OUTPUT')

     DECLARE @SupportSQL_OutGrabber nvarchar(max)
     SET @SupportSQL_OutGrabber = N'SET @OUTPUT = CONVERT(nvarchar(max),@' + @OUT_VARIABLE + N');'

     SET @SQL = N'DECLARE @SQL nvarchar(max) = N''' + @SQL + ''''
     

     --Build the dynamic string to run
     SET @SQL =	@SupportSQL_Header + N';' + CHAR(13)+CHAR(10) +
     			@SupportSQL_Parameters + N';' + CHAR(13)+CHAR(10) +
     			@SQL + N';' + CHAR(13)+CHAR(10) +
     			@SupportSQL_Footer + N';' + CHAR(13)+CHAR(10) +
        COALESCE(@SupportSQL_OutGrabber,N'')
     
     --PRINT @SQL

     UPDATE dbo.DYNSQL_LOG
      SET DynamicSQL = @SQL
     WHERE Id = @ID
     
     BEGIN TRY

      EXEC sp_executesql @SQL, N'@OUTPUT nvarchar(max) OUTPUT', @OUTPUT = @RETURN OUTPUT --DUMMY OUTPUT VALUE

     END TRY
     BEGIN CATCH
      UPDATE dbo.DYNSQL_LOG
       SET EndTime = SYSDATETIME(),
       Failed = 1,
       ErrorMsg = LEFT(ERROR_MESSAGE(),256)
      WHERE Id = @ID
      
      IF(@SKIP_ERRORS = 0)
       THROW

     END CATCH

     --SELECT @RETURN

END;

UPDATE dbo.DYNSQL_LOG
    SET EndTime = SYSDATETIME()
WHERE Id = @ID

END
GO

Let’s start by analyzing  a simple Dynamic SQL statement with no parameters, it works like this:

DECLARE @SQL nvarchar(max) = 'SELECT ''I AM ALIVE'' as Wasssup'
EXEC [ExecuteAndTrackSQL] @SQL = @SQL

1. Gets the username (if not set as parameter) and inserts a row in the Logging table with the code and the start time (and Tag, eventually)
2. Saves the identity just inserted in the Log table by using SCOPE_IDENTITY() in order to get back at the end and update that row with the end time.
3. If there are no parameters, I’ll just try to execute the code via sp_executesql
   1. If it fails, I update the log row with the error details (and if the procedure is not set to ignore errors, raises the error to the caller)
   2. If it doesn’t, it updates the Log row with the end time and returns

In this case, it’s very straight forward; Let’s expand with the parametric query:

Since this is not a special procedure that accepts an arbitrary number of parameters like sp_executesql, I had to improvise on how to pass such arbitrary data, and I’ve opted for the Table type option:

CREATE TYPE SQLParameters AS TABLE
(   
    Name NVARCHAR(50),
    Value NVARCHAR(max),
    Type NVARCHAR(20) DEFAULT N'NVARCHAR(20)'
);
GO

I’ve created this type that will basically hold the input parameters to pass into the Stored Procedure; I had to use the nvarchar type and then cast stuff around inside the procedure as I think that’s still better than using the sql_variant type, I’ll use the [Type] column to convert the value to the right datatype inside the procedure itself. This procedure supports even output parameters, but just one, and it will be returned regardless of the original type as an nvarchar(max), which then should be converted back to the original data type.

An example is worth a thousand words:

DECLARE @Parameters AS SQLParameters;

INSERT INTO @Parameters
VALUES (N'Param1',N'Please Select me','nvarchar(100)')

DECLARE @SQL nvarchar(max) = 'SELECT @Param1 as Selected'
EXEC [ExecuteAndTrackSQL] @SQL = @SQL, @PARAM_VALUES = @Parameters

This simply selects the value of the @Param1 parameter that we just passed in the parameters list, but you get the idea. What if you want to explicitly output a parameter value? It’s similar to sp_executesql:

DECLARE @Parameters AS SQLParameters;
DECLARE @ReturnValue AS nvarchar(max);

INSERT INTO @Parameters
VALUES (N'Param1',N'Please Select me','nvarchar(100) OUTPUT')

DECLARE @SQL nvarchar(max) = 'SET @Param1 = ''Oh Oh, you changed me'''
EXEC [ExecuteAndTrackSQL] @SQL = @SQL, @PARAM_VALUES = @Parameters, @RETURN = @ReturnValue OUTPUT

SELECT @ReturnValue as ReturnValue

The parameter needs to be defined by the OUTPUT keyword in the type column, and the @Return value of the stored procedure to be fetched with the OUTPUT keyword too. It’s not so far away from the original syntax, but here you have to populate the parameters into a Table variable, as opposed to a string.

As far as the code goes, I’m roughly doing the following: Creating some Dynamic SQL code that will run some Dynamic SQL code to run the SQL Code of the user. There are 3 main parts:

1. @SupportSQL_Header
   • Used to create the parameters as variables in the Dynamic SQL Scope
2. @SupportSQL_Parameters
   • Used to create the @Parameters string for sp_executesql listing all the parameters
3. @SQL Variable
   • The @SQL string passed as parameter in the stored procedure is encapsulated inside a local (to the dynamic SQL) @SQL Variable
4. @SupportSQL_Footer
   • Used to generate a sp_executesql statement that will execute the dynamic SQL Code using the parameters and @SQL statement above
5. @SupportSQL_OutGrabber
   • Whenever there is an output value, this is used to grab the Output parameter value

This is the content of each part as in the example above:

--@SupportSQL_Header    
SET NOCOUNT ON;
DECLARE @Param1 as nvarchar(100)  = N'Please Select me'

--@SupportSQL_Parameters
DECLARE @Parameters nvarchar(max) = N'@Param1 as nvarchar(100) OUTPUT'

--@SQL Variable
DECLARE @SQL nvarchar(max) = N'SET @Param1 = ''Oh Oh, you changed me''';

--@SupportSQL_Footer
EXEC sp_executesql @SQL, @Parameters, @Param1 = @Param1 OUTPUT

--@SupportSQL_OutGrabber
SET @OUTPUT = CONVERT(nvarchar(max),@Param1);

These statements will be then concatenated and executed by another sp_executesql run that uses a dummy output variable.

So, that’s it. This can be easily used for non-parametrized dynamic SQL as-is, as you just need to replace sp_executesql with ExecuteAndTrackSQL, the rest is the same, a little bit more complicated (and with limitations) when using parameters (especially output parameters)