#0180 – SQL Server – Profiler – SQL:StmtCompleted shows parameters, not their values


The SQL Server Profiler is a very powerful diagnostic tool that helps you take a look at what’s happening inside of SQL Server when you execute a query. I hope that you are finding the 10-part tutorial series on the SQL Server Profiler (http://beyondrelational.com/modules/12/tutorials/631/getting-started-with-sql-server-profiler.aspx?tab=tutorials&bs=57&ts=46) useful. The aim of the tutorial is to help you get started with the SQL Server profiler and debug any database issues within your application with ease.

However, the more you explore, the more queries and questions you come up with and attempting to answer them is perhaps the best way to learn.

One of the kind readers asked me a question the other day via the ASK Module (http://beyondrelational.com/ask/nakul/default.aspx) related to the SQL Server Profiler (http://beyondrelational.com/ask/nakul/questions/1557/sql-server-profiler-trace-query.aspx), the answer to which I will discussing in today’s post.

The Question

Assume that one of your applications is executing the following query to get a list of all salaried employees for AdventureWorks Cycles.

USE AdventureWorks2012
GO
SELECT * FROM HumanResources.Employee WHERE SalariedFlag = 1

However, when looked at from the SQL Server Profiler, you see that instead of the value “1”, you see a parameterized version of the query if the “SQL:StmtStarting” or “SQL:StmtCompleted” events are captured:

SELECT * FROM HumanResources.Employee WHERE SalariedFlag = @p1

The actual parameter value (“1”) is available when the “RPC:Completed” event is captured. The question therefore is:

Why do “SQL:StmtStarting” and “SQL:StmtCompleted” not show the parameter values? Is there a way by which they can show the parameter values, so that additional events don’t need to be traced?

The Answer

The question is very interesting, and the answer lies in the internals of how SQL Server prepares itself for multiple executions of the same query in the future. However, let’s answer the second part of the question first. The answer to the second part of the question is quite simply, no. To the best of my knowledge, there is no way that we can have both the parameterized version of the query and it’s values captured the same event – “SQL:StmtStarting” or “SQL:StmtCompleted”.

That being said, let’s look at “why” the parameterized version of the query is seen.

One of the first things that SQL Server’s database engine does is to create a query plan for execution. Preparing a query plan is an expensive operation and therefore, SQL Server caches this plan for future re-use. Subsequent executions of the query will re-use the already available query plan and not spend time in creating a new plan – the specific values used in the comparisons may differ from instance to instance, but the plan itself remains the same.

We are therefore looking at two different components to the execution of a query:

  1. A generic, parameterized query plan – which is what is seen in the “SQL:StmtStarting” and “SQL:StmtCompleted” events
  2. A set of instance-specific variables/parameter values – which is what is seen in the instance specific “RPC:Completed” event

The following is an easy set of queries for better understanding of the concept.

/* WARNING */
/*
This query is provided "as-is" and without warranty.
The query is provided for demonstration purposes only.

PLEASE RUN THIS ON A DEVELOPMENT ENVIRONMENT ONLY.
EXECUTING THIS ON A QA/PRODUCTION ENVIRONMENT MAY RESULT IN SERIOUS PERFORMANCE COMPLICATIONS.
*/
DBCC FREEPROCCACHE
DBCC DROPCLEANBUFFERS

USE AdventureWorks2008R2
GO
DECLARE @sqlstring NVARCHAR(100)
DECLARE @paramDefinition NVARCHAR(50)
DECLARE @paramValue BIT

SET @sqlstring = N'SELECT * FROM HumanResources.Employee WHERE SalariedFlag = @p1'
SET @paramDefinition = N'@p1 BIT'
SET @paramValue = 1

EXEC sp_executesql @sqlstring, @paramDefinition, @p1 = @paramValue

--Check if the SQL Server is re-using the query plan
-- USECOUNTS value should be 1
SELECT usecounts, cacheobjtype, objtype, text 
FROM sys.dm_exec_cached_plans 
CROSS APPLY sys.dm_exec_sql_text(plan_handle) 
WHERE usecounts > 0 AND 
    	text like '%SELECT * FROM HumanResources.Employee%'
ORDER BY usecounts DESC;

/********* RESULTS ****************/
/* (Compressed for sake of brevity)
usecounts   cacheobjtype	objtype	     text
  1         Compiled Plan	Prepared     (@p1 BIT)SELECT * FROM HumanResources.Employee WHERE SalariedFlag = @p1
  1         Compiled Plan	Adhoc        DECLARE @sqlstring ...............
*/

We can see that the version SQL Server has cached is the one with the generalized parameters – not the one with the parameter values.

image

Let us execute the same query again – this time with a different parameter value.

--Execute the query again, but with a different value
SET @paramValue = 0
EXEC sp_executesql @sqlstring, @paramDefinition, @p1 = @paramValue

--Check if the SQL Server is re-using the query plan
-- USECOUNTS value should be 2
SELECT usecounts, cacheobjtype, objtype, text 
FROM sys.dm_exec_cached_plans 
CROSS APPLY sys.dm_exec_sql_text(plan_handle) 
WHERE usecounts > 0 AND 
    	text like '%SELECT * FROM HumanResources.Employee%'
ORDER BY usecounts DESC;

/********* RESULTS ****************/
/* (Compressed for sake of brevity)
usecounts   cacheobjtype	objtype	     text
  2         Compiled Plan	Prepared    (@p1 BIT)SELECT * FROM HumanResources.Employee WHERE SalariedFlag = @p1
  1         Compiled Plan	Adhoc       DECLARE @sqlstring ...............
*/
GO

The results show that the SQL Server was able to reuse the generic query plan.

image

Reference:

Until we meet next time,

Be courteous. Drive responsibly.

Advertisements

6 thoughts on “#0180 – SQL Server – Profiler – SQL:StmtCompleted shows parameters, not their values

  1. rojipt

    On what environments you have tested this? Was Foreced Parameterization in effect? From which client you invoked the queries?

    In my tests in both 28R2 and 2012 I get the exact text in the “SQL:StmtStarting” and “SQL:StmtCompleted” events.

    Like

    Reply
  2. Nakul Vachhrajani

    Thank-you for the questions! This was tested on SQL Server 2008 R2. For the test, forced parameterization was not in effect and the queries were fired from a test application (as mentioned when introducing the question). Please note that in-line query was not used. The test application (a simple .NET application with the standard data access methods, which I gather are parameterized by default) was run both – locally on the server, and remote.

    Like

    Reply
  3. rojipt

    Thanks. I was trying to validate what you are suggesting in the blog. So are you saying that this is just an issue with the client and it has nothing to with Profiler?

    Like

    Reply
  4. Nakul Vachhrajani

    Well, it’s not an issue at all – both systems – the client and the profiler are working exactly as designed.

    Every query can be looked as being made up of two components – a static component (i.e. the query plan) and the instance-specific component (i.e. the value of the variables). Therefore, when the “RPC: Starting” or “RPC: Completed” events are monitored in the Profiler, one gets instance-specific information, i.e. information specific to that particular execution, and therefore one gets the values of the variables here. But, the “SQL: StmtStarting” or “SQL:StmtCompleted” events are the static component of the query and hence do not display the variable values.

    It’s like the relationship between a multi-purpose screw-driver and it’s fittings – the handle part remains constant, but the fittings may change based on the execution instance.

    Like

    Reply
  5. rojipt

    Nakul,

    Allow me to disagree. AFAIK, The correlation between the execultion plan (or instance specific execution context) and the profiler events are not correct. The RPC (Remote Procedure Call) events are traced from the higher stacks, Not the execution engine.

    Like

    Reply
  6. rojipt

    I thought I should offer an explanation on how we can prove they are unrelated.

    1. Run the trace and try to run a proc that does not exist. The RPC Starting and RPC completed Events will show the proc call, but it will fail with “cannot find procedure” error.

    2. Create a new proc (or alter an existing one) and run the proc after setting up trace for all Stored Procedure category events. You can see the compilation events happening after the RPC Starting event.

    Like

    Reply

Let me know what you think about this post by leaving your feedback here!

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s