THE SQL Server Blog Spot on the Web

Welcome to SQLblog.com - The SQL Server blog spot on the web Sign in | |
in Search

Tibor Karaszi

Is there and overhead to RPC events?

I recently read a discussion whether RPC events add overhead compared to just submitting text. I got curious and did some testing, which I want to share.

Background, SQL events
Using most APIs, if you just submit a query to SQL Server, you will get what we call an SQL event (for instance in Profiler an SQL:BatchCompleted). The client app submits some text, SQL Server parses the text, and either creates an execution pland or re-uses a cached plan (if such exists, based on checksum of the query text submitted). Now, this is very straight forward. But there's also problems, mainly risk for SQL Injection and bad query plan re-use. Your query probably has a WHERE clause, and if you just concatenate the values you will have in the WHERE clause, then you will submit different text each time. Different text means different execution plans - bad plan re-use. Also, if you have some malicious user or are under hacker-attack, then somebody can inject some query or part of query inside what you think would be only the search value (this is a classic).

Stored procedures as RPC events
Now, consider if we are using stored procedures. We might want to pass the proc name, and the values for each parameter, where we pass the parameter values as binary data. Do this right (for instance in ADO, you configure your command object's CommandType property as being CommandType.StoredProcedure (instead of CommandType.Text which is default). This causes the batch be shown in Profiler as an RPC event, for instance RPC:Completed. So, consider executing the same procedure either by constructing a string such as "EXEC myProc @p1 = '20080223', @p2 = 'Stockholm'" as text (SQL event), or passing it as a stored procedure using parameter objects (RPC event). We expect RPC event to be more efficient, right? We'll get to that in a moment.

Queries as RPC events
Now, we can also submit queries, without using stored procedures, so they are passed as RPC events. We do this by adding at least one parameter to the command object. This causes ADO.NET to use an RPC event and execute sp_executesql, parameterizing accoring to the parameter object for the command object. This causes your code to be safe from SQL injection and will allow for better plan re-use. I.e., in most cases a very good thing - second best to use stored procedures!

Non-parameterized queries as RPC events
Now, consider if we don't want to parameterize our queries (we don't have a WHERE clause, we just don't want to, we use some programming layer which doesn't allow for it, or we are just plan curious - like now). Can we still get RPC events? Yes, by adding a dummy parameter to the command object. We don't have to use this command object in the query - just the existence causes an RPC event instead of SQL event. This allow us to compare SQL events to RPC event and look at only the overhead for the sp_executesql part.

Overhead for using sp_executesql
Below is some VB.NET code which does just that. For the first two, we use exactly the same query multiple executions and compare timing for doing them as SQL events or RPC events. For the second two, we change what produceID we search for (but not parameterizing the search condition) which causes different execution plans for each execution. I verified by counting execution plans that the first two uses the same execution pland and the second two generates a new plan for each iteration in the loop. Here's the VB.NET code:

Imports System.Data
Imports System.Data.SqlClient
Module Module1

    
Sub Main()

        
Dim As Int32iterations As Int32 20000
        
Dim tickcount As Int64
        
Dim ProductID As Int32 43664
        
Dim ProdStatus As Int16
        
Dim sql As String

        
sql "SELECT status FROM Sales.SalesOrderHeader WHERE SalesOrderID = "
        
Dim cn As New SqlConnection("SERVER=localhost\a;DATABASE=AdventureWorks2008;INTEGRATED SECURITY=TRUE")
        
cn.Open()

        
Dim utilCmd As New SqlCommand("DBCC FREEPROCCACHE"cn)
        
utilCmd.ExecuteNonQuery()

        
'Definitions
        '**********************************************************************************************
        'Same query every execution, SQL:BatchCompleted
        
Dim cmdAllText As New SqlCommand(sql "43664"cn)
        
cmdAllText.CommandType CommandType.Text

        
'Same query every execution, RPC:Completed
        
Dim cmdParmText As New SqlCommand(sql "43664"cn)
        
cmdParmText.CommandType CommandType.Text
        cmdParmText.Parameters.Add
("@dummy"SqlDbType.Int)
        
cmdParmText.Parameters("@dummy").Value -9999

        
'Different query every execution, SQL:BatchCompleted
        
Dim cmdAllText2 As New SqlCommand()
        
cmdAllText2.Connection cn
        cmdAllText2.CommandType 
CommandType.Text

        
'Different query every execution, RPC:Completed
        
Dim cmdParmText2 As New SqlCommand()
        
cmdParmText2.Connection cn
        cmdParmText2.CommandType 
CommandType.Text
        cmdParmText2.Parameters.Add
("@dummy"SqlDbType.Int)
        
cmdParmText2.Parameters("@dummy").Value -9999



        
'Execution
        '**********************************************************************************************
        
Console.WriteLine("Same query every execution, SQL:BatchCompleted")
        
tickcount Environment.TickCount
        
For To iterations
            ProdStatus 
cmdAllText.ExecuteScalar()
        
Next
        
tickcount Environment.TickCount tickcount
        
Call PrintOuput(iterationstickcount)

        
Console.WriteLine("Same query every execution, RPC:Completed")
        
tickcount Environment.TickCount
        
For To iterations
            ProdStatus 
cmdParmText.ExecuteScalar()
        
Next
        
tickcount Environment.TickCount tickcount
        
Call PrintOuput(iterationstickcount)

        
Console.WriteLine("Different query every execution, SQL:BatchCompleted")
        
tickcount Environment.TickCount
        
For To iterations
            cmdAllText2.CommandText 
sql i.ToString()
            
ProdStatus cmdAllText2.ExecuteScalar()
        
Next
        
tickcount Environment.TickCount tickcount
        
Call PrintOuput(iterationstickcount)

        
Console.WriteLine("Different query every execution, RPC:Completed")
        
tickcount Environment.TickCount
        
For To iterations
            cmdParmText2.CommandText 
sql i.ToString()
            
ProdStatus cmdParmText2.ExecuteScalar()
        
Next
        
tickcount Environment.TickCount tickcount
        
Call PrintOuput(iterationstickcount)

        
Console.ReadLine()

    
End Sub

    Sub 
PrintOuput(ByVal iterations As Int32ByVal tickcount As Int64)
        
Console.WriteLine("Number of executions: " iterations.ToString)
        
Console.WriteLine("Total exec time (ms): " tickcount)
        
Console.WriteLine("Exec time per query (ms): " tickcount iterations)
        
Console.WriteLine("")
    
End Sub


End 
Module

And here's a typical execution result from above code:

Same query every execution, SQL:BatchCompleted
Number of executions: 20000
Total exec time (ms): 1357
Exec time per query (ms): 0,06785

Same query every execution, RPC:Completed
Number of executions: 20000
Total exec time (ms): 1513
Exec time per query (ms): 0,07565

Different query every execution, SQL:BatchCompleted
Number of executions: 20000
Total exec time (ms): 2402
Exec time per query (ms): 0,1201

Different query every execution, RPC:Completed
Number of executions: 20000
Total exec time (ms): 14446
Exec time per query (ms): 0,7223

As you can see, there is an overhead to use RPC events and sp_executesql. I.e., if we don't parameterize our command object, then we only pay with no gain. The overhead is definitely noticeable were we generate a new plan for each execution. An interesting aspect is that if I remove the call to DBCC FREEPROCCACHE, (so we get new plan for each iteration in the loop, but plans can be re-used from prior execution of the VB code), then this is much cheaper and closer to the others (about 5.7 seconds instead of 14 seconds). So, we do pay extra for sp_executesql especially when we generate a new plan.

Is above a weird example?
Yes, it is, and I want to emphasize that. Typically, you will use sp_executesql when you actually parameterize your queries. That will cause better plan re-use (and protect from SQL injection). Above is only to show whether sp_executesql has a cost - without considering the benefits.

How about using stored procedures?
Say you are using stored procedures, and wonder how different ways to execute a procedure compares? Let's have a look. We can do it three ways (probably more, but below are the ones I'm interested in):

  1. Build the proc command and pass it as a string. No parameter objects, no sp_executesql. You are still open to SQL injection. Don't do this, we only want to show it for comparsion reasons. Profiler will show an SQL:BatchCompleted event with TextData something like "EXEC dbo.GetOrderStatusRes @SalesOrderID = 43664".
  2. Use parameters for your command objects, but you forget to define the command object of type CommandType.StoredProcedure. Profiler will show an RPC:Completed event with TextData something like "exec sp_executesql N'EXEC dbo.GetOrderStatusRes @SalesOrderID = @theID',N'@theID int',@theID=43664".
  3. The right way. Define the command object as of type CommandType.StoredProcedure, and of course add parameter object to the command object. Profiler will show an RPC:Completed event with TextData something like:
    "declare @p2 tinyint
    set @p2=5
    exec dbo.GetOrderStatusOut @SalesOrderID=43664,@Status=@p2 output
    select @p2"
    Note that the Profiler tool adds the declare, set and select parts, it is not part of what is submitted from the client app. The client app actually submit the paramaters as binary values. Profiler add this to be nice to us, so we can copy that text and execute it, read it, etc.

Anyhow, here's the VB code:

Imports System.Data
Imports System.Data.SqlClient
Module Module1

    
Sub Main()

        
Dim As Int32iterations As Int32 20000
        
Dim tickcount As Int64
        
Dim ProductID As Int32 43664
        
Dim ProdStatus As Int16
        
Dim sql As String

        Dim 
cn As New SqlConnection("SERVER=localhost\a;DATABASE=AdventureWorks2008;INTEGRATED SECURITY=TRUE")
        
cn.Open()

        
'Create the procedures we will execute
        
Dim utilCmd As New SqlCommand(""cn)
        
utilCmd.CommandText "IF OBJECT_ID('dbo.GetOrderStatusRes') IS NOT NULL DROP PROC dbo.GetOrderStatusRes" vbCrLf
        utilCmd.CommandText 
+"IF OBJECT_ID('dbo.GetOrderStatusOut') IS NOT NULL DROP PROC dbo.GetOrderStatusOut"
        
utilCmd.ExecuteNonQuery()
        
utilCmd.CommandText "CREATE PROC dbo.GetOrderStatusRes @SalesOrderID int AS SELECT status FROM Sales.SalesOrderHeader WHERE SalesOrderID = @SalesOrderID"
        
utilCmd.ExecuteNonQuery()
        
utilCmd.CommandText "CREATE PROC dbo.GetOrderStatusOut @SalesOrderID int, @status tinyint OUT AS SET @status = (SELECT status FROM Sales.SalesOrderHeader WHERE SalesOrderID = @SalesOrderID)"
        
utilCmd.ExecuteNonQuery()

        
'Run each once so it is in cache
        
utilCmd.CommandText "EXEC dbo.GetOrderStatusRes @SalesOrderID = 43664"
        
utilCmd.ExecuteScalar()
        
utilCmd.CommandText "DECLARE @s tinyint EXEC dbo.GetOrderStatusOut @SalesOrderID = 43664, @status = @s OUT"
        
utilCmd.ExecuteNonQuery()

        
utilCmd.CommandText "DBCC FREEPROCCACHE"

        
'Definitions
        '**********************************************************************************************
        'Exec proc as string, SQL:BatchCompleted
        
Dim cmdAllText As New SqlCommand("EXEC dbo.GetOrderStatusRes @SalesOrderID = " ProductID.ToString(), cn)
        
cmdAllText.CommandType CommandType.Text

        
'Parameterize, but still as text, RPC:Completed with sp_executesql
        
Dim cmdParmText As New SqlCommand("EXEC dbo.GetOrderStatusRes @SalesOrderID = @theID"cn)
        
cmdParmText.CommandType CommandType.Text
        cmdParmText.Parameters.Add
("@theID"SqlDbType.Int)
        
cmdParmText.Parameters("@theID").Value ProductID

        
'Parameterize as stored procedure, RPC:Completed
        
Dim cmdRpc As New SqlCommand("dbo.GetOrderStatusOut"cn)
        
cmdRpc.CommandType CommandType.StoredProcedure
        
Dim prmSalesOrderID As SqlParameter = New SqlParameter("@SalesOrderID"SqlDbType.Int)
        
prmSalesOrderID.Value ProductID
        cmdRpc.Parameters.Add
(prmSalesOrderID)
        
Dim prmStatus As SqlParameter = New SqlParameter("@Status"SqlDbType.TinyInt)
        
prmStatus.Direction ParameterDirection.Output
        
cmdRpc.Parameters.Add(prmStatus)


        
'Execution
        '**********************************************************************************************
        
utilCmd.ExecuteNonQuery()
        
Console.ReadLine()

        
Console.WriteLine("Exec proc as string, SQL:BatchCompleted")
        
tickcount Environment.TickCount
        
For To iterations
            ProdStatus 
cmdAllText.ExecuteScalar()
        
Next
        
tickcount Environment.TickCount tickcount
        
Call PrintOuput(iterationstickcount)
        
Console.ReadLine()

        
utilCmd.ExecuteNonQuery()
        
Console.WriteLine("Parameterize, but still as text, RPC:Completed with sp_executesql")
        
tickcount Environment.TickCount
        
For To iterations
            ProdStatus 
cmdParmText.ExecuteScalar()
        
Next
        
tickcount Environment.TickCount tickcount
        
Call PrintOuput(iterationstickcount)
        
Console.ReadLine()

        
utilCmd.ExecuteNonQuery()
        
Console.WriteLine("Parameterize as stored procedure, RPC:Completed")
        
tickcount Environment.TickCount
        
For To iterations
            cmdRpc.ExecutteNonQuery
()
        
Next
        
tickcount Environment.TickCount tickcount
        
Call PrintOuput(iterationstickcount)

        
Console.ReadLine()

    
End Sub
    Sub 
PrintOuput(ByVal iterations As Int32ByVal tickcount As Int64)
        
Console.WriteLine("Number of executions: " iterations.ToString)
        
Console.WriteLine("Total exec time (ms): " tickcount)
        
Console.WriteLine("Exec time per query (ms): " tickcount iterations)
        
Console.WriteLine("")
    
End Sub

End 
Module

And here's the result from a typical execution:

Exec proc as string, SQL:BatchCompleted
Number of executions: 20000
Total exec time (ms): 1810
Exec time per query (ms): 0,0905

Parameterize, but still as text, RPC:Completed with sp_executesql
Number of executions: 20000
Total exec time (ms): 1700
Exec time per query (ms): 0,085

Parameterize as stored procedure, RPC:Completed
Number of executions: 20000
Total exec time (ms): 1388
Exec time per query (ms): 0,0694

We can see that doing it the "proper" way is cheapest, but there's not a big difference between the three. The first alternative is not good, though, since we aren't protected from SQL injection. And since you then will be using parameter object anyhow, just go ahead and define the CommandType as stored procedure while you're at it.

Published Monday, January 11, 2010 12:31 PM by TiborKaraszi
Filed under: ,

Comment Notification

If you would like to receive an email when updates are made to this post, please register here

Subscribe to this post's comments using RSS

Comments

 

djo said:

Great post and examples.   It taught me a ton.

February 5, 2011 9:51 AM
 

jack kangas said:

There is something else happening in the RPC:Completed step - some sort of cleanup that I can't find documentation for.

(pls don't comment on users code - I don't have control and my head already hurts)

I have a load progrram that is doing 30M select and then insert and every 1/2 second or so - either the insert or select will have a duration of about 1.5 seconds - while the pageiolatch_sh and writelog waits go up.

But the other 99% of the time the select takes .55ms and insert takes .8ms (800 microseconds).

There is no Un_prepare step being sent in - is that the cause/reason for the sudden uptick.

I don't see any memory grants pending and the disk queue lengths don't show anything - disk queue legnth jumps up and then back down to zero.

Any clues jack"dot"kangas"attsign"cbc"dash"companies"dot"com

February 11, 2011 9:44 AM
 

Anon said:

Awesome expirement.  Very helpful.

August 4, 2013 11:37 AM

Leave a Comment

(required) 
(required) 
Submit

This Blog

Syndication

Powered by Community Server (Commercial Edition), by Telligent Systems
  Privacy Statement