Fun With Logging Dynamic SQL

Last Updated 7 years ago

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

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!

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)
);

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

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

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!

SQL Server 2017 Release Date: May 31?

Free Webcast Next Tuesday: How to Triage SQL Server Emergencies

9 Comments. Leave new

Martin Guth
April 12, 2017 12:29 am

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

Reply
- Erik Darling
  April 12, 2017 7:18 am
  
  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.
  
  Reply
Patrick Dadey
April 16, 2017 9:06 pm

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?

Reply
- Erik Darling
  April 16, 2017 10:31 pm
  
  I only use it in dynamic SQL to simplify adding on additional predicates in the WHERE clause.
  
  Reply
Chuck Rummel
April 26, 2017 8:49 pm

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.

Reply
- Erik Darling
  April 27, 2017 7:37 am
  
  Hahaha, isn’t it funny how almost nothing has changed or improved around how dynamic SQL gets used in… forever?
  
  Reply
Kris
October 5, 2020 11:24 pm

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’), …

Reply
- Brent Ozar
  October 6, 2020 2:50 am
  
  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!
  
  Reply
  - Kris
    October 6, 2020 2:58 am
    
    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.
    
    Reply