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:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
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.
Logging Tables
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!
|
1 2 3 4 5 6 7 8 9 10 |
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.
|
1 2 3 4 5 6 7 8 9 10 11 12 |
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.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
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 |
Logjammin’
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.
That’s you.
Thanks for reading!
9 Comments. Leave new
Hi Erik,
nice blog post. I especially love the statement ” I log in as sa because I am the app and the app is me”. Maybe I should rephrase it to “I am the DBA and the DBA is me” while dealing with stubborn users :-).
All the best
Martin
It’d be even more impressive if you were on a DBA team and did a whole Rockettes style high-kick dance while singinging “we are the DBAs and the DBAs are we” — mind your tights don’t rip though.
Hey Eric sounds like you are @one with the app :-).
On another note it is good to see someone else use WHERE 1 = 1. Is that an artefact of dynamic SQL or do you use it out of convention?
I only use it in dynamic SQL to simplify adding on additional predicates in the WHERE clause.
I did similar things about 15 years ago. It helped me prove that users almost never supplied input for any of the dozens of parameters on the “Swiss Army Knife” proc; and by adding a call at the end to sp_user_counter1 we could directly expose that procedure’s execution time through perfmon rather than keep a profiler trace running on prod all the time. Good times.
Hahaha, isn’t it funny how almost nothing has changed or improved around how dynamic SQL gets used in… forever?
Not sure about the REPLACE, but maybe I’m over reacting … I mean, it must take some measurable time to do a REPLACE on Ahem! 60K of dynamic SQL, and maybe the ISNULLs cost some too … although I have never tested how much CONCAT costs 🙂 but I favour CONCAT so that I can store @parameters separately to @command in my Logger table
@Parameters = CONCAT(‘@i_PostTypeId=’, @PostTypeId, ‘, @i_UserId=’, @UserId, ‘, @i_Top=’, @Top)
in part because I would like to see the dynamic SQL as-was to avoid possible confusion over any REPLACE modifications, I do have to watch loss of precision on some datatypes using CONCAT
On the occasions when I care about whether a string parameter is EMPTY or NULL I can either do
CONCAT(‘@s_Name=’, ””+@s_Name+””)
and realise that EMPTY means NULL, given that is what CONCAT is going to do for the non-string params, or
CONCAT(‘@s_Name=’, ISNULL(””+@s_Name+””, ‘NULL’))
but if I want oven-ready parameters for sp_executesql I would need to use ISNULL for all of them which, unless you have a crafty idea, means doing type conversion casts for all non-strings
@Parameters = CONCAT(‘@i_PostTypeId=’, ISNULL(CONVERT(varchar(20), @PostTypeId), ‘NULL’), …
Hi! I’m not sure if you’re asking a question – if this is a question, can you post it on a Q&A site like https://dba.stackexchange.com? Thanks!
Appreciate you taking the time to reply, thanks, and sorry my comment was badly worded.
It was a suggestion to LOG Parameters separately from Command as I think only storing the Command (with REPLACE) may make solving some problems more challenging due to loss of detail when checking the LOG later.