July 1, 2016 at 8:13 am
Hey all,
I've been pulling some data on a server we're tuning and one of the things I was looking for was excessive execution of queries, etc... I found a reporting SP that said it was executed over 57,000 times in a < 24 hour period. My first thought was "Oh man, something is really wrong!"
So I set up a profiler to look for the RPC Complete on this particular SP, and I wasn't getting anything, but yet the execution_count continued to click up on it. So I went in and actually executed the SSRS report that calls that procedure, and I saw the execution_count tick up *AND* I saw the RPC complete show up in my profiler.
So my problem... I no longer can trust the execution_count numbers from this DMV and I really need this data to keep up with this (and other) servers. The number is increasing when the SP is not actually executing, and I've found other instances of this as well on other SP's. I've focused on the reporting ones because those are all interactive or scheduled reports and it is much easier to determine when those were actually run versus the procedures associated to the applications. But if it is happening on these reporting procedures, I have to believe it is happening elsewhere and now all this data is suspect.
I found someone else having the same issue on the link below, but my questions for this group:
1) Can someone explain what is going on and why it might be doing this?
2) Is there a way to fix this or another way I should be getting execution_counts?
As a quick sanity check I focused on just the reporting procedures...
I queried the DMV and saved the execution count
I did a WAITFOR 2 minutes
I re-queried the DMV and saved that execution count
Then I compared that versus the report execution log in ReportServer.
No entries of the report being run, but some of the report counts had increased by 4 to 15 execution counts in that 2 minutes.
Any help would be appreciated!
July 1, 2016 at 8:15 am
And I can't spell "execution" it is one of those days! 🙂
October 8, 2016 at 7:27 am
I've still never figured this out...anyone have any ideas? Please? 🙂
October 10, 2016 at 1:43 pm
I assume you mean "sys.dm_exec_procedure_stats" although you never really stated that.
I suspect it has something to do with SSRS. Maybe the proc is being called from the SSRS web page/interface?
Books Online does mention this:
"
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.
"
but it seems clear this issue goes beyond just the first use or two of that DMV.
SQL DBA,SQL Server MVP(07, 08, 09) "It's a dog-eat-dog world, and I'm wearing Milk-Bone underwear." "Norm", on "Cheers". Also from "Cheers", from "Carla": "You need to know 3 things about Tortelli men: Tortelli men draw women like flies; Tortelli men treat women like flies; Tortelli men's brains are in their flies".
October 11, 2016 at 12:57 am
Hi Scott,
That is correct. I ran a trace looking for all calls of some of the specific report procedures. If I executed it via SSRS I would see the count go up, and see it in the trace without issue. I left it running for a few hours, came back and saw no more executions in the trace, but in sys.dm_exec_procedure_stats the execution count had gone up by 200+
I really can't explain the behavioiur and I've now see it on more than just reports, it is prevalent throughout many stored procedures, but it is not consistent. I posted this on the administration forum as well and there is some more conversation going there. After finding another guy with the same issue I've adapted this to use a combination of the dm_exec_procedure_stats with the sys.dm_exec_query_stats. These are returning different numbers, but I've watched in realtime as the dm_exec_procedure_stats skews and overcounts actual executions, while the dm_exec_query_stats (a max on all the plans for that objectID) matches reality. This has made my tracking query more complex, but hopefully more reliable and realistic. Now I'm concerned about the worker time and elapsed time, because those also differ between the two sometimes too. 🙁
This is obviously a work in progress, but it is where I've come to so far, but my trust level is not high.
select
db_name(database_ID) as [Database_Name]
,p.Name
,pstats.object_id
,cached_time
,last_execution_time
--,execution_count
,COALESCE(qstats.execution_count,pstats.execution_count) as [Execution_Count]
,CAST(total_worker_time as DECIMAL(15,0))/1000000 as [WorkerTime_Total_s]
,CAST(last_worker_time as DECIMAL(15,0))/1000000 as [WorkerTime_Last_s]
,CAST(min_worker_time as DECIMAL(15,0))/1000000 as [WorkerTime_Min_s]
,CAST(max_worker_time as DECIMAL(15,0))/1000000 as [WorkerTime_Max_s]
--,CAST(total_worker_time as DECIMAL(15,0))/1000000/execution_count as [WorkerTime_Avg_s]
,CAST(total_worker_time as DECIMAL(15,0))/1000000/COALESCE(qstats.execution_count,pstats.execution_count) as [WorkerTime_Avg_s]
,CAST(total_elapsed_time as DECIMAL(15,0))/1000000 as [ElapsedTime_Total_s]
,CAST(last_elapsed_time as DECIMAL(15,0))/1000000 as [ElapsedTime_Last_s]
,CAST(min_elapsed_time as DECIMAL(15,0))/1000000 as [ElapsedTime_Min_s]
,CAST(max_elapsed_time as DECIMAL(15,0))/1000000 as [ElapsedTime_Max_s]
--,CAST(total_elapsed_time as DECIMAL(15,0))/1000000/execution_Count as [ElapsedTime_Avg_s]
,CAST(total_elapsed_time as DECIMAL(15,0))/1000000/COALESCE(qstats.execution_count,pstats.execution_count) as [ElapsedTime_Avg_s]
,create_date
,Modify_date
,GETDATE()
from
sys.dm_exec_procedure_stats pstats
left join
sys.procedures p
on
pstats.object_ID=p.object_id
left join
(
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
from sys.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 DB_Name(st.dbid) is not null
group by st.objectID, st.dbid
) qstats
on
qstats.[ObjectID] = pstats.Object_ID
AND
qstats.[db_id] = db_id()
WHERE
database_id = db_id()
ScottPletcher (10/10/2016)
I assume you mean "sys.dm_exec_procedure_stats" although you never really stated that.I suspect it has something to do with SSRS. Maybe the proc is being called from the SSRS web page/interface?
Books Online does mention this:
"
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.
"
but it seems clear this issue goes beyond just the first use or two of that DMV.
Viewing 5 posts - 1 through 4 (of 4 total)
You must be logged in to reply to this topic. Login to reply