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
- 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)
- 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.
- If there are no parameters, I’ll just try to execute the code via sp_executesql
- 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)
- 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:
- @SupportSQL_Header
- Used to create the parameters as variables in the Dynamic SQL Scope
- @SupportSQL_Parameters
- Used to create the @Parameters string for sp_executesql listing all the parameters
- @SQL Variable
- The @SQL string passed as parameter in the stored procedure is encapsulated inside a local (to the dynamic SQL) @SQL Variable
- @SupportSQL_Footer
- Used to generate a sp_executesql statement that will execute the dynamic SQL Code using the parameters and @SQL statement above
- @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)
