While working on a demo
I thought this might make a fun aside to share on the blog, because working with dynamic SQL can be challenging. Especially if you don’t have a monitoring tool or application profiling to figure out who ran what and when, most of the time you’ll have no idea what went wrong.
For example, the dynamic SQL that my query produces (sometimes) looks like this:
SELECT u.DisplayName, SUM(CONVERT(BIGINT, u.UpVotes)) AS [UpVotes], SUM(CONVERT(BIGINT, u.DownVotes)) AS [DownVotes], SUM(CONVERT(BIGINT, u.Reputation)) AS [Reputation] , SUM(CONVERT(BIGINT, p.CommentCount)) AS [TotalComments], SUM(CONVERT(BIGINT, p.Score)) AS TotalScore , SUM(CONVERT(BIGINT, c.Score)) AS [CommentScore] FROM Users AS u JOIN Posts AS p ON p.OwnerUserId = u.Id JOIN Comments AS c ON c.UserId = u.Id AND c.PostId = p.Id WHERE 1 = 1 AND u.Id = @i_UserId AND p.PostTypeId = @i_PostTypeId GROUP BY u.DisplayName ORDER BY SUM(CONVERT(BIGINT, u.Reputation)) DESC
Notice those two variables in the WHERE clause? Part of how using parameterized dynamic SQL protects you is by not just sticking whatever stinky nonsense users submit directly in to your dynamic SQL block. That’s also what makes it challenging to troubleshoot. Sure, you can head to the plan cache, but you may not find anything there.
If your company is too cheap to get you monitoring tools, well, that’s another discussion. If you want to figure out why dynamic queries are slow anyway, here’s one option. Without showing you all of what my dynamic SQL does, I’ll show you how the logging works. It starts with a table!
CREATE TABLE dbo.Logger ( Id BIGINT IDENTITY(1, 1), RunHash UNIQUEIDENTIFIER, UserName NVARCHAR(128), StartTime DATETIME2, EndTime DATETIME2, RunTimeSeconds AS DATEDIFF(SECOND, StartTime, EndTime), DynamicSQL NVARCHAR(MAX) );
You can add in more stuff if you want, this is just the bare minimum I’d collect.
Now, in the stored procedure, you can do something like this.
DECLARE @RunHash UNIQUEIDENTIFIER = NEWID() ...Whole Mess O' Stuff... INSERT dbo.Logger ( RunHash, UserName, StartTime, EndTime, DynamicSQL ) VALUES(@RunHash, SUSER_SNAME(), SYSDATETIME(), NULL, @Command) EXEC sys.sp_executesql 'Your lousy query' UPDATE dbo.Logger SET EndTime = SYSDATETIME() WHERE RunHash = @RunHash
But all that will log is your dynamic SQL with the variables. What I prefer to do is spin up a placeholder that I can replace values in without messing with the dynamic SQL to be executed. Since this command will never be executed, I can use REPLACE to figure out what my values are.
DECLARE @PrettyPrint NVARCHAR(MAX) = N'' DECLARE @RunHash UNIQUEIDENTIFIER = NEWID() SELECT @PrettyPrint = REPLACE( REPLACE( REPLACE(@Command, '@i_PostTypeId', ISNULL(@PostTypeId, N'') ), '@i_UserId', ISNULL(@UserId, N'') ), '@i_Top', ISNULL(@Top, N'') ) INSERT dbo.Logger ( RunHash, UserName, StartTime, EndTime, DynamicSQL ) VALUES(@RunHash, SUSER_SNAME(), SYSDATETIME(), NULL, @PrettyPrint) UPDATE dbo.Logger SET EndTime = SYSDATETIME() WHERE RunHash = @RunHash
I double logged my stored proc calls so you can get a better idea of what happens. Here’s what my logging table looks like:
You can already see one spot where an optional @Top was substituted with the actual number “the user” asked for. Don’t give me any application security guff here, I log in as sa because I am the app and the app is me.
Zooming in on where the other variables live in the WHERE clause, now we can see which ones were called.
This can pose some security risk. If some malicious person were to realize that you’re logging these calls, they could change your code to execute the printable version instead. If security is a concern, you may want to offload the logging code to other stored procedures.
If you want to really ball out on this one, you could even frame the replaced values in special delimiters like ‘||’ and then parse those out as well. But I’ll leave that as an exercise for the reader.
Thanks for reading!