May 26, 2016 at 10:34 am
Hello all.
I was trying to use the DMV noticed to track the frequency of SPs running on SQL Server 2008 R2
At the initial stage, I've go the results from sys.dm_exec_procedure_stats into temp table as shown below:
select
qs.plan_handle
,DB_NAME (qs.database_id) DBName
,p.Name as objName
,qs.execution_count execution_count
into sp_stats
FROM sys.procedures AS p WITH (NOLOCK)
INNER JOIN sys.dm_exec_procedure_stats AS qs WITH (NOLOCK) ON p.[object_id] = qs.[object_id]
where qs.database_id=DB_ID()
and p.name not like 'MSmerge%'
and p.name not like 'sp[_]%'
A the same time I've started a trace to catch all RPC:Complete events
after approximately 20 minutes I've gotten anothe snapshot using the query above into the sp_stats_after_20m table
comparing the results, I've found that in the new snapshot exist records that are not in the first one
for example, in the new snapshot (sp_stats_after_20m) the record is appeared for some SP, say SP1 with execution_count=2431, but the trace said, that there was only 1 run for that 20 minutes
reexamining the view shown the same.
So, "An initial query of sys.dm_exec_procedure_stats might produce inaccurate results if there is a workload currently executing on the server. More accurate results may be determined by rerunning the query." as the BOL said is incorrect
I was trying to rerun the query, but the execution_count was the same
the execution_count and other statistics for SP1 when server is under high load is exluded from sys.dm_exec_procedure_stats, and at the time when it runs again, appeared in sys.dm_exec_procedure_stats with old results in execution_count, but diffent plan_handle, so it is difficult to analyze, on which execution plan that sp belongs. The situation goes more complicated when there are several plans for the same SP. Some rarely used plans exluded from the cache when high load, and when these plans are in use again, thay have the old execution_counts, but different plan_handle
May 26, 2016 at 10:52 am
Exactly how are you comparing the before and after results (the query used)?
For the trace, are you sure there are no filters configured? Exactly how are you querying the trace results to determine execution count there?
Cheers!
EDIT: Fixed a typo
May 26, 2016 at 10:57 am
the query to compare results is:
select *,a.execution_count-isnull(case when a.execution_count>=b.execution_count then b.execution_count else 0 end,0) delta
from sp_stats_after_20m a full join sp_stats b on a.objName=b.objName and a.plan_handle=b.plan_handle
where a.objName is null or b.objName is null
and there are results with SP1 and execution_count = 2431, while in the trace is only 1 run
actually the sp name was something like p_blah_blahblah (not SP1)
the trace definition is:
-- Create a Queue
declare @rc int
declare @TraceID int
declare @maxfilesize bigint
set @maxfilesize = 15
declare @filecount int=6
declare @traceFile nvarchar(500)= --'C:\Data\MSSQL10_50.MSSQLSERVER\MSSQL\trace\SPExecLog'
N'X:\MSSQL10_50.MSSQLSERVER\MSSQL\Trace\SPExecLog'
exec @rc = sp_trace_create @TraceID output, 2, @traceFile,
@maxfilesize, NULL ,@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, 43, 15, @on
exec sp_trace_setevent @TraceID, 43, 34, @on
exec sp_trace_setevent @TraceID, 43, 3, @on
exec sp_trace_setevent @TraceID, 43, 12, @on
exec sp_trace_setevent @TraceID, 43, 22, @on
exec sp_trace_setevent @TraceID, 43, 62, @on
-- Set the Filters
declare @intfilter int
declare @bigintfilter bigint
exec sp_trace_setfilter @TraceID, 34, 0, 6, N'atisp%'
exec sp_trace_setfilter @TraceID, 34, 1, 6, N'p[_]%'
exec sp_trace_setfilter @TraceID, 34, 0, 1, NULL
-- 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
so the filter is only for SP names ... no other filters
All that have place only when the server is under high pressure. when the proc cache is full, and server's engine decides to eliminate some rarely used SP stats from the cache
Right now, for example, I can't reproduce the issue, only on rush hours. When there are ~4K queries per second ... Now there are ~1K. So the issue is not reproduced
June 1, 2016 at 4:05 am
Hello all again!
Is it glitch of MS I've posted above?
Anyway, it seems I've reached my goal.
select
st.dbid db_id
,st.objectID
,isNull(OBJECT_NAME(st.objectID,st.dbid),'') as objName
,DB_Name(st.dbid) DBName
,max(execution_count) execution_count
fromsys.dm_exec_query_stats qs
cross apply sys.dm_exec_sql_text(sql_handle) as st
where total_logical_reads >0
and isNull(OBJECT_NAME(st.objectID,st.dbid),'') not like 'MSmerge%'
and isNull(OBJECT_NAME(st.objectID,st.dbid),'') not like 'sp[_]%'
and DB_Name(st.dbid) is not null
group by st.objectID, st.dbid
investigating the DMV sys.dm_exec_query_stats I've found that for one SP it has number of records. Each record refers to the specific code in SP that has separate execution plan. in the query above I get MAX execution_count from the DMV grouping by SP name (and DB of course). In this case, when some of plan is removed from the cache, the other plans (in most cases) still exist there. I gather the results from the query every 3 minutes. And store them into staging table. I populate the table by next algorothm: if
there no records for specific SP, I insert it with execution_count value and delta=0 (the delta in this cas is to populate number of executions between measurements), otherwise I update delta by statement: delta =source.execution_count-case when source.execution_count>=target.execution_count then target.execution_count else 0 end
The sample code is below:
insert into #statdata(
id_db
,objectID
,objName
,DBName
,execution_count
) <select * from prev query>
update target set
delta =source.execution_count-case when source.execution_count>=target.execution_count then target.execution_count else 0 end
,dtPrevUpdate=dtLastUpdate
,dtLastUpdate=GETDATE()
,execution_count=source.execution_count
from SL.cur_SP_Stats as target
join #statdata as source
on (target.id_db = source.id_db and target.objectID=source.objectID and target.idServer=@idServer)
insert SL.cur_SP_Stats
select *,0,@idServer,GETDATE(),null from #statdata a
where not exists(select 1 from SL.cur_SP_Stats b (nolock) where a.DBName=b.DBName and a.objName=b.objName and b.idServer=@idServer)
the @idServer is used b/c I have to monitor several servers
the table SL.cur_SP_Stats:
CREATE TABLE [SL].[cur_SP_Stats](
[id_db] [int] NULL,
[objectID] [int] NULL,
[objName] [nvarchar](255) NULL,
[DBName] [nvarchar](100) NULL,
[execution_count] [bigint] NULL,
[delta] [int] NOT NULL,
[idServer] [int] NULL,
[dtLastUpdate] [datetime] NOT NULL,
[dtPrevUpdate] [datetime] NULL
) ON [PRIMARY]
GO
ALTER TABLE [SL].[cur_SP_Stats] ADD DEFAULT ((0)) FOR [idServer]
GO
ALTER TABLE [SL].[cur_SP_Stats] ADD DEFAULT (getdate()) FOR [dtLastUpdate]
GO
ALTER TABLE [SL].[cur_SP_Stats] ADD DEFAULT (getdate()) FOR [dtPrevUpdate]
GO
The next step I've done - the storing of the intermediate results into the log table (to analyze the trends and etc)
the log table is:
CREATE TABLE [SL].[SP_exec_Stats](
[dtExecDate] [datetime] NOT NULL,
[prcName] [sysname] NOT NULL,
[idServer] [int] NOT NULL,
[db] [sysname] NOT NULL,
[delta] [bigint] NOT NULL,
CONSTRAINT [PK_SP_exec_Stats] PRIMARY KEY CLUSTERED
(
[dtExecDate] ASC,
[prcName] ASC,
[idServer] ASC,
[db] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]
the code that populates the log is:
CREATE TRIGGER [SL].[tr_cur_SP_stats_ins_upd]
ON [SL].[cur_SP_Stats]
AFTER INSERT,UPDATE
AS
BEGIN
-- SET NOCOUNT ON added to prevent extra result sets from
-- interfering with SELECT statements.
SET NOCOUNT ON;
;merge SL.SP_exec_Stats t
using inserted s
on t.dtExecDate=cast(CONVERT(char(8),s.dtLastUpdate,112)+' '+CONVERT(char(2),s.dtLastUpdate,114)+':00:00' as datetime)
and t.prcName=s.objName
and t.idServer=s.idServer
and t.db=s.DBName
when matched
then update
set delta=t.delta+s.delta
when not matched by target
then insert
values(cast(CONVERT(char(8),s.dtLastUpdate,112)+' '+CONVERT(char(2),s.dtLastUpdate,114)+':00:00' as datetime),s.objName,s.idServer,s.DBName,s.delta);
END
to make the analyze more easy I am grouping the executions by 1 hour
Hope it would help others to reach the same goal
Viewing 4 posts - 1 through 3 (of 3 total)
You must be logged in to reply to this topic. Login to reply