JDBC applications (and some ORMs) are notorious for sending sp_prepexec, followed by sp_execute, calls to SQL Server, instead of sending the actual SQL command. Generally this is fine until you need to see the actual command with parameters that is being sent from your client to SQL Server. This is common when troubleshooting. I have yet to find any DMVs or logging mechanisms on the SQL Server side that can do this.
Example
The first call to your SQL Server may look like this in Profiler:
declare @p1 int
set @p1=1
exec sp_prepexec @p1 output,N'@name varchar(128)',N'exec MyProc @name',@name=’SomeVariable'
select @p1
The output of @p1 we’ll asume is 73. Each call to sp_prepexec will get a new @p1 OUTPUT value from SQL Server. Note that the client is trying to assign @P1 to be 1, and SQL Server can choose to honor that request or not. It probably won’t.
Subsequent calls when using Prepared Execution will look something like this:
exec sp_execute 1,’Something’
All subsequent calls will look like this until either the client or SQL Server loses the @P1 mapping. For instance, if either is low on memory the cache may be cleared. On the client side the solution is simple…another sp_prepexec statement is sent. On the SQL Server, if the cache was cleared then the sp_execute call from the client will generate an error which will force the client to send a new sp_prepexec call.
The problem is that the @P1 cached call may remain in cache for hours or even days. When it comes to troubleshooting a client call, how do we get anything useful from exec sp_execute 1,’Something’, such as a stored procedure name?
One Possible Solution
I’ve worked on a project where I knew prepared execution was going to be a nightmare. We mandated that the last parameter to EVERY stored procedure was called @ParameterName with a DEFAULT of NULL. Our data API knew to append this value to all database queries. This made our calls look like this:
exec sp_execute 1,’Something’, ‘MyProc’
Problem solved. Of course, designing a system like this takes forethought.
Another Solution
Profiler can still be used with RPC:Completed events if you also add SP:CacheHit. The two events will have the same StartTime so we can match the two events. Note that you can filter for specific things as normal (database id for instance), but SP:CacheHit will add some overhead on a production system, and it cannot be filtered. If you enable it you will see instance-wide SP:CacheHit events. Use with caution.
Here is the SQLTrace definition:
-- declare variables
declare @rc int
declare @TraceID int
declare @databaseid int
declare @piOptions int
declare @filecount int
declare @maxfilesize bigint
declare @stoptime datetime
-- set variables
-- @TraceID is output from trace initializataion
set @databaseid = (SELECT TOP 1 DATABASE_ID FROM SYS.DATABASES WHERE NAME LIKE '%TND%')
set @piOptions = 2
set @filecount = 20
set @maxfilesize = 2000
set @stoptime = (SELECT DATEADD(HOUR, 8, GETDATE()));
-- Set this to Null to include subprocedures in the cachehit results.
-- Set to 8272 to filter out cache hits of subprocedures
declare @ObjectType INT
set @ObjectType = 8272
-- Please replace the text InsertFileNameHere, with an appropriate
-- filename prefixed by a path, e.g., c:\MyFolder\MyTrace. The .trc extension
-- will be appended to the filename automatically. If you are writing from
-- remote server to local drive, please use UNC path and make sure server has
-- write access to your network share
exec @rc = sp_trace_create @TraceID output, @piOptions, N'V:\Backup02\TraceData\SIM_20120411_SQLPerf_Trace', @maxfilesize, @stoptime, @filecount
if (@rc != 0) goto error
-- Client side File and Table cannot be scripted
-- Set the events
declare @on bit
set @on = 1
exec sp_trace_setevent @TraceID, 100, 1, @on
exec sp_trace_setevent @TraceID, 100, 3, @on
exec sp_trace_setevent @TraceID, 100, 13, @on
exec sp_trace_setevent @TraceID, 100, 14, @on
exec sp_trace_setevent @TraceID, 100, 16, @on
exec sp_trace_setevent @TraceID, 100, 17, @on
exec sp_trace_setevent @TraceID, 100, 18, @on
exec sp_trace_setevent @TraceID, 100, 26, @on
exec sp_trace_setevent @TraceID, 100, 27, @on
exec sp_trace_setevent @TraceID, 100, 34, @on
exec sp_trace_setevent @TraceID, 10, 1, @on
exec sp_trace_setevent @TraceID, 10, 3, @on
exec sp_trace_setevent @TraceID, 10, 13, @on
exec sp_trace_setevent @TraceID, 10, 14, @on
exec sp_trace_setevent @TraceID, 10, 16, @on
exec sp_trace_setevent @TraceID, 10, 17, @on
exec sp_trace_setevent @TraceID, 10, 18, @on
exec sp_trace_setevent @TraceID, 10, 26, @on
exec sp_trace_setevent @TraceID, 10, 27, @on
exec sp_trace_setevent @TraceID, 10, 34, @on
exec sp_trace_setevent @TraceID, 38, 1, @on
exec sp_trace_setevent @TraceID, 38, 3, @on
exec sp_trace_setevent @TraceID, 38, 13, @on
exec sp_trace_setevent @TraceID, 38, 14, @on
exec sp_trace_setevent @TraceID, 38, 16, @on
exec sp_trace_setevent @TraceID, 38, 17, @on
exec sp_trace_setevent @TraceID, 38, 18, @on
exec sp_trace_setevent @TraceID, 38, 26, @on
exec sp_trace_setevent @TraceID, 38, 27, @on
exec sp_trace_setevent @TraceID, 38, 34, @on
exec sp_trace_setevent @TraceID, 35, 1, @on
exec sp_trace_setevent @TraceID, 35, 3, @on
exec sp_trace_setevent @TraceID, 35, 13, @on
exec sp_trace_setevent @TraceID, 35, 14, @on
exec sp_trace_setevent @TraceID, 35, 16, @on
exec sp_trace_setevent @TraceID, 35, 17, @on
exec sp_trace_setevent @TraceID, 35, 18, @on
exec sp_trace_setevent @TraceID, 35, 26, @on
exec sp_trace_setevent @TraceID, 35, 27, @on
exec sp_trace_setevent @TraceID, 35, 34, @on
exec sp_trace_setevent @TraceID, 34, 1, @on
exec sp_trace_setevent @TraceID, 34, 3, @on
exec sp_trace_setevent @TraceID, 34, 13, @on
exec sp_trace_setevent @TraceID, 34, 14, @on
exec sp_trace_setevent @TraceID, 34, 16, @on
exec sp_trace_setevent @TraceID, 34, 17, @on
exec sp_trace_setevent @TraceID, 34, 18, @on
exec sp_trace_setevent @TraceID, 34, 26, @on
exec sp_trace_setevent @TraceID, 34, 27, @on
exec sp_trace_setevent @TraceID, 34, 34, @on
-- Set the Filters
declare @intfilter int
declare @bigintfilter bigint
-- add filter if not null
IF (@databaseid IS NOT NULL)
BEGIN
set @intfilter = @databaseid
exec sp_trace_setfilter @TraceID, 3, 1, 0, @intfilter
END
exec sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Server Profiler - aa92e090-c828-4681-a4bf-ffe4a3f1e972'
IF (@ObjectType IS NOT NULL)
BEGIN
set @intfilter = @ObjectType
exec sp_trace_setfilter @TraceID, 28, 0, 1, @intfilter
END
exec sp_trace_setfilter @TraceID, 28, 0, 1, 21076
-- Set the trace status to start
exec sp_trace_setstatus @TraceID, 1
-- display trace id for future references
select TraceID=@TraceID
goto finish
error:
select ErrorCode=@rc
finish:
go
