December 5, 2013 at 6:48 am
Hi Experts,
we have a list of procedures used when accessing a particular application.
Is there anyway to check how long this procedures take to complete?
If i ran profiler and click on the app buttons i can see those procedures running behind. Can i get the time it ran? Is there any other way other than profiler??
December 5, 2013 at 7:04 am
There are, but what's wrong with running profiler (or preferably a server-side trace) and recording the duration column?
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
December 9, 2013 at 2:05 pm
I've been using a procedure written by Gregory A. Larsen. It will display the top worst performing queries. It comes in quite handy and may help you out. Here is the code:
USE [master]
GO
/****** Object: StoredProcedure [dbo].[usp_Worst_TSQL] Script Date: 12/09/2013 16:03:41 ******/
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
ALTER PROC [dbo].[usp_Worst_TSQL]
/*
Written by: Gregory A. Larsen
Copyright © 2008 Gregory A. Larsen. All rights reserved.
Name: usp_Worst_TSQL
Description: This stored procedure displays the top worst performing queries based on CPU, Execution Count,
I/O and Elapsed_Time as identified using DMV information. This can be display the worst
performing queries from an instance, or database perspective. The number of records shown,
the database, and the sort order are identified by passing pararmeters.
Parameters: There are three different parameters that can be passed to this procedures: @DBNAME, @COUNT
and @ORDERBY. The @DBNAME is used to constraint the output to a specific database. If
when calling this SP this parameter is set to a specific database name then only statements
that are associated with that database will be displayed. If the @DBNAME parameter is not set
then this SP will return rows associated with any database. The @COUNT parameter allows you
to control the number of rows returned by this SP. If this parameter is used then only the
TOP x rows, where x is equal to @COUNT will be returned, based on the @ORDERBY parameter.
The @ORDERBY parameter identifies the sort order of the rows returned in descending order.
This @ORDERBY parameters supports the following type: CPU, AE, TE, EC or AIO, TIO, ALR, TLR, ALW, TLW, APR, and TPR
where "ACPU" represents Average CPU Usage
"TCPU" represents Total CPU usage
"AE" represents Average Elapsed Time
"TE" represents Total Elapsed Time
"EC" represents Execution Count
"AIO" represents Average IOs
"TIO" represents Total IOs
"ALR" represents Average Logical Reads
"TLR" represents Total Logical Reads
"ALW" represents Average Logical Writes
"TLW" represents Total Logical Writes
"APR" represents Average Physical Reads
"TPR" represents Total Physical Read
Typical execution calls
Top 6 statements in the AdventureWorks database base on Average CPU Usage:
EXEC usp_Worst_TSQL @DBNAME='AdventureWorks',@COUNT=6,@ORDERBY='ACPU';
Top 100 statements order by Average IO
EXEC usp_Worst_TSQL @COUNT=100,@ORDERBY='ALR';
Show top 100 statements by Average IO
EXEC usp_Worst_TSQL;
- Updated: 4/14/2014 Added "LET" represents Last Execution Time
*/
(
--declare
@DBNAME VARCHAR(128) = ''
,@COUNT INT = 99999
,@ORDERBY VARCHAR(4) = 'AIO'
,@FromDateTime DATETIME = null
,@ToDateTime DATETIME = null
)
AS
set nocount on
-- Check for valid @ORDERBY parameter
IF ((SELECT CASE WHEN @ORDERBY in ('ACPU','TCPU','AE','TE','EC','AIO','TIO','ALR','TLR','ALW','TWL','APR','TPR', 'LET') THEN 1 ELSE 0 END) = 0)
BEGIN
-- abort if invalid @ORDERBY parameter entered
RAISERROR('@ORDERBY parameter not ACPU, TCPU, AE, TE, EC, AIO, TIO, ALR, TLR, ALW, TLW, APR, LET or TPR',11,1)
RETURN
END
declare @IgnoreDB table (ID int primary key identity (1,1)
,Database_Name varchar(300)
)
insert into @IgnoreDB (Database_Name) values ('ProjectServer_Draft')
insert into @IgnoreDB (Database_Name) values ('ProjectServer_Published')
insert into @IgnoreDB (Database_Name) values ('Resource')
insert into @IgnoreDB (Database_Name) values ('Search_Service_Application_DB_c8785b3aa44a4764b0033694e891b403')
insert into @IgnoreDB (Database_Name) values ('Search_Service_Application_PropertyStoreDB_3ec06be4caa54e6d903263a2940815eb*')
insert into @IgnoreDB (Database_Name) values ('SharePoint_Config')
insert into @IgnoreDB (Database_Name) values ('WSS_Logging')
insert into @IgnoreDB (Database_Name) values ('WSS_Content')
insert into @IgnoreDB (Database_Name) values ('Search_Service_Application_CrawlStoreDB_af930aab0a8b48609df53c5572fb5213')
insert into @IgnoreDB (Database_Name) values ('Managed Metadata Service_77e8fbe186ba4becbd25cfb12d4b41ff')
insert into @IgnoreDB (Database_Name) values ('Managed Metadata Service_77e8fbe186ba4becbd25cfb12d4b41ff*')
insert into @IgnoreDB (Database_Name) values ('msdb')
SELECT TOP (@COUNT)
COALESCE(DB_NAME(st.dbid), DB_NAME(CAST(pa.value AS INT)) + '*', 'Resource') AS [Database Name]
-- find the offset of the actual statement being executed
,SUBSTRING(text,
CASE WHEN statement_start_offset = 0
OR statement_start_offset IS NULL THEN 1
ELSE statement_start_offset/2 + 1 END,
CASE WHEN statement_end_offset = 0
OR statement_end_offset = -1
OR statement_end_offset IS NULL THEN LEN(text)
ELSE statement_end_offset/2 END -
CASE WHEN statement_start_offset = 0
OR statement_start_offset IS NULL
THEN 1
ELSE statement_start_offset/2 END + 1
) AS [Statement]
,OBJECT_SCHEMA_NAME(st.objectid,dbid) AS [Schema Name]
,OBJECT_NAME(st.objectid,dbid) AS [Object Name]
,case when @ORDERBY = 'ACPU' then qs.total_worker_time / qs.execution_count
when @ORDERBY = 'TCPU' then qs.total_worker_time
when @ORDERBY = 'AE' then qs.total_elapsed_time / qs.execution_count
when @ORDERBY = 'TE' then total_elapsed_time
when @ORDERBY = 'EC' then execution_count
when @ORDERBY = 'AIO' then (total_logical_reads + total_logical_writes + total_physical_reads) / execution_count
when @ORDERBY = 'TIO' then total_logical_reads + total_logical_writes + total_physical_reads
when @ORDERBY = 'ALR' then total_logical_reads / execution_count
when @ORDERBY = 'TLR' then total_logical_reads
when @ORDERBY = 'ALW' then total_logical_writes / execution_count
when @ORDERBY = 'TLW' then total_logical_writes
when @ORDERBY = 'APR' then total_physical_reads / execution_count
when @ORDERBY = 'TPR' then total_physical_reads
-- when @ORDERBY = 'LET' then last_execution_time
end AS [Sorted Column]
,qs.last_execution_time AS [Last Execution Time]
,objtype AS [Cached Plan objtype]
,qs.execution_count AS [Execution Count]
,(qs.total_logical_reads + qs.total_logical_writes + qs.total_physical_reads )/qs.execution_count AS [Average IOs]
,qs.total_logical_reads + qs.total_logical_writes + qs.total_physical_reads AS [Total IOs]
,qs.total_logical_reads/qs.execution_count AS [Avg Logical Reads]
,qs.total_logical_reads AS [Total Logical Reads]
,qs.total_logical_writes/qs.execution_count AS [Avg Logical Writes]
,qs.total_logical_writes AS [Total Logical Writes]
,qs.total_physical_reads/qs.execution_count AS [Avg Physical Reads]
,qs.total_physical_reads AS [Total Physical Reads]
,qs.total_worker_time / qs.execution_count AS [Avg CPU]
,qs.total_worker_time AS [Total CPU]
,qs.total_elapsed_time / qs.execution_count AS [Avg Elapsed Time]
,qs.total_elapsed_time AS [Total Elasped Time]
FROM sys.dm_exec_query_stats qs join
sys.dm_exec_cached_plans cp ON qs.plan_handle = cp.plan_handle cross apply
sys.dm_exec_sql_text(qs.plan_handle) st outer apply
sys.dm_exec_plan_attributes(qs.plan_handle) pa left join
@IgnoreDB idb on DB_NAME(st.dbid) = idb.Database_Name left join
@IgnoreDB idb1 on DB_NAME(CAST(pa.value AS INT)) = idb1.Database_Name
WHERE attribute = 'dbid' AND
CASE when @DBNAME = '' THEN '' ELSE COALESCE(DB_NAME(st.dbid),DB_NAME(CAST(pa.value AS INT)) + '*', 'Resource') END IN (RTRIM(@DBNAME),RTRIM(@DBNAME) + '*')
-- AND cast(qs.last_execution_time as datetime) >= isnull(@FromDateTime, cast('01/01/2001 00:00:00' as datetime))
AND cast(qs.last_execution_time as datetime) between isnull(@FromDateTime, cast('01/01/2001 00:00:00' as datetime)) and isnull(@ToDateTime, GETDATE())
and ISDATE(qs.last_execution_time) = 1
and idb.ID is null
and idb1.ID is null
ORDER BY CASE WHEN @ORDERBY = 'ACPU' THEN total_worker_time / execution_count
WHEN @ORDERBY = 'TCPU' THEN total_worker_time
WHEN @ORDERBY = 'AE' THEN total_elapsed_time / execution_count
WHEN @ORDERBY = 'TE' THEN total_elapsed_time
WHEN @ORDERBY = 'EC' THEN execution_count
WHEN @ORDERBY = 'AIO' THEN (total_logical_reads + total_logical_writes + total_physical_reads) / execution_count
WHEN @ORDERBY = 'TIO' THEN total_logical_reads + total_logical_writes + total_physical_reads
WHEN @ORDERBY = 'ALR' THEN total_logical_reads / execution_count
WHEN @ORDERBY = 'TLR' THEN total_logical_reads
WHEN @ORDERBY = 'ALW' THEN total_logical_writes / execution_count
WHEN @ORDERBY = 'TLW' THEN total_logical_writes
WHEN @ORDERBY = 'APR' THEN total_physical_reads / execution_count
WHEN @ORDERBY = 'TPR' THEN total_physical_reads
-- WHEN @ORDERBY = 'LET' THEN cast(last_execution_time as datetime)
END DESC
, cast(last_execution_time as datetime) desc
Kurt
Kurt W. Zimmerman
SR DBA
Lefrak Organization
New York, NY
http://www.linkedin.com/in/kurtwzimmerman
December 26, 2013 at 1:56 pm
I would say Profiler is still the best, as it gives you a lot of flexibility in analyzing the collected trace data (doing such analysis via T-SQL on the trace data saved into table (via trace files first) is better than just using Profiler GUI)).
As far as taking a look at your most often executed procedures/sql statements that take the longest duration as well,
I find the following DMV based query very useful (as it contains Query Plans in XML format that you can click on and see plans):
SELECT TOP 50
CAST(qs.total_elapsed_time / 1000000.0 AS DECIMAL(28, 2))
AS [Total Duration (s)]
, qs.execution_count
, SUBSTRING (qt.text, (qs.statement_start_offset/2) + 1,
((CASE WHEN qs.statement_end_offset = -1
THEN LEN(CONVERT(NVARCHAR(MAX), qt.text)) * 2
ELSE
qs.statement_end_offset
END - qs.statement_start_offset/2) + 1)) [indiv/query]
, qt.text AS [Parent Query]
, DB_NAME(qt.dbid) AS DatabaseName
, qp.query_plan
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) qt
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) qp
ORDER BY total_elapsed_time DESC
Likes to play Chess
Viewing 4 posts - 1 through 3 (of 3 total)
You must be logged in to reply to this topic. Login to reply