Measure T-SQL / Stored Procedure Performance
If you are using SQL Server or dealt with SQL Server in any fashion, you might have heard this million times, How do you measure the TSQL ( Adhoc ) or Stored Procedure Performance.
I have been using Microsoft SQL Server for more than 10 years now. My primary focus is building products to solve the Business Problem and Add Business Value to the Team. I am not an expert in SQL Server Internals , for that matter , its not open Source. Unless, you work for SQL Sever team , its very hard to understand how a particular piece of code works to produce a simple functionality. I always find Paul Randalls Blog Posts more accurate explaining SQL Server Internals.
I have written lot of Stored Procedures , T-SQL Statements in my career. Even though I have written so many stored procedures, I always encounter the same Questions.
How do I measure my Stored Procedure or T-SQL Performance?.
Measurement in terms of IO Operations
CPU Measurement
Memory
For example, sometimes I run half marathons. I enjoy drinking and running helps with that aspect of my life.Half Marathon is 13.1 Mile and I exactly know how far I have to run to finish my half . Mile is good unit of Measure where we all understand that half marathon is 13.1 Miles. It doesn’t matter what part of the world you are, as long as you use Miles , you know whats 13.1 miles means.
Just like Mile for measuring distance, whats a good unit for measuring TSQL or Stored Procedure Performance?.
I find logical Reads being good unit of Measurement for Stored Procedure or TSQL Performance. Its almost like pages in a book.
Lets say , you have a novel with 300 pages. Some Readers finish that in 2 hours and some others take about 5 years based on how fast they read.
OK. Logical Reads Good Unit of Measurement for Stored Procedure or T-SQL Performance.
What is it?
Logical read is defined as reading a page ( 8 KB ) from Memory. SQL Sever Pages consist of 8 KB.
Microsoft Definition :
“The I/O from an instance of SQL Server is divided into logical and physical I/O. A logical read occurs every time the database engine requests a page from the buffer cache. If the page is not currently in the buffer cache, a physical read is then performed to read the page into the buffer cache. If the page is currently in the cache, no physical read is generated; the buffer cache simply uses the page already in memory.”
OK. How do I Capture this Value?.
SET STATISTICS IO ON
GO
Use the above setting to turn on the Statistics. You will see the Logical Reads for the stored procedure or T-SQL Statement.
The other question arises?. In the printed book, sometimes you see 300 pages for regular print. Some People request Large Print and the same content end up in 400 pages. For the reader who’s reading it, it probably take same time for finishing the novel except they have to turn more pages but the content is same. Its laid in large font for readabilty.
Does the Same Rule applicable for SQL Server?.
If the SQL Server read 300 pages, now it needs to read 400 pages to get the same content. Theres nothing in SQL Server equates to Large Print but we can equate that to fillfactor and pad index. We can equate that to how densely each page is filled with Data.
Obviously , same content is spread over 400 pages instead of 300 pages mean, you need to read more pages. Thats additional work but that leaves some room in the page where you can pack additional data.
So Logical Reads are good unit of Measure but it can be misleading at tims based on how densely each page is filled.But its far more better indicator than every thing else.
SET STATISTICS TIME ON
GO
This statement would give you the value of CPU Time spend.
Does this take into account of faster CPU vs Slower CPU. CPU is usually measured on Hertz.
From WIKIPEDIA
The speed that a CPU works at is measured in “Hertz“, “Hz”. Modern processors often run so fast that “Gigahertz”, “GHz”, is used instead. One gigahertz is one billion hertz.
How can we translate the CPU spent on a particular T-SQL Statement or Stored Procedure.
Memory:
How much memory being spent on a particular TSQL or Stored Procedure. What if the memory of the computer is not big enough to fit the data fetched. That means, more round trips needs to happen between the memory and Disk .
Stored Procedure Use Count Stats
SELECT DB_NAME(st.dbid) DBName ,
OBJECT_SCHEMA_NAME(st.objectid, dbid) SchemaName ,
OBJECT_NAME(st.objectid, dbid) StoredProcedure ,
MAX(cp.usecounts) Execution_count
FROM sys.dm_exec_cached_plans cp
CROSS APPLY sys.dm_exec_sql_text(cp.plan_handle) st
WHERE DB_NAME(st.dbid) IS NOT NULL
AND cp.objtype = 'proc'
AND DB_NAME(st.dbid) = '[DBName]'
AND OBJECT_NAME(st.objectid, dbid) LIKE '%[ObjectName]%'
GROUP BY cp.plan_handle ,
DB_NAME(st.dbid) ,
OBJECT_SCHEMA_NAME(objectid, st.dbid) ,
OBJECT_NAME(objectid, st.dbid)
ORDER BY MAX(cp.usecounts)
Stored Procedures Calling Rate :
SELECT
OBJECT_NAME(qt.objectid)
, qs.execution_count AS [Execution Count]
, qs.execution_count / DATEDIFF(Second, qs.creation_time, GETDATE()) AS [Calls/Second]
, qs.total_worker_time / qs.execution_count AS [AvgWorkerTime]
, qs.total_worker_time AS [TotalWorkerTime]
, qs.total_elapsed_time / qs.execution_count AS [AvgElapsedTime]
, qs.max_logical_reads
, qs.max_logical_writes
, qs.total_physical_reads
, DATEDIFF(Minute, qs.creation_time, GETDATE()) AS [Age in Cache Min]
FROM
sys.dm_exec_query_stats AS qs
CROSS APPLY
sys.dm_exec_sql_text(qs.[sql_handle]) AS qt
WHERE
qt.[dbid] = DB_ID()
ORDER BY
qs.execution_count DESC
OPTION (RECOMPILE);
-- To Clare the Stats gathered
DBCC SQLPERF("sys.dm_os_wait_stats",CLEAR);
SELECT
OBJECT_NAME(qt.objectid)
, qs.execution_count AS [Execution Count]
, qs.execution_count / DATEDIFF(Second, qs.creation_time, GETDATE()) AS [Calls/Second]
, qs.total_worker_time / qs.execution_count AS [AvgWorkerTime]
, qs.total_worker_time AS [TotalWorkerTime]
, qs.total_elapsed_time / qs.execution_count AS [AvgElapsedTime]
, qs.max_logical_reads
, qs.max_logical_writes
, qs.total_physical_reads
, DATEDIFF(Minute, qs.creation_time, GETDATE()) AS [Age in Cache]
FROM
sys.dm_exec_query_stats AS qs
CROSS APPLY
sys.dm_exec_sql_text(qs.[sql_handle]) AS qt
WHERE
qt.[dbid] = DB_ID()
AND qt.objectid = OBJECT_ID('StoredProcedureName')
OPTION (RECOMPILE);
SELECT DB_NAME(st.dbid) DBName
,OBJECT_SCHEMA_NAME(st.objectid,dbid) SchemaName
,OBJECT_NAME(st.objectid,dbid) StoredProcedure
,max(cp.usecounts) Execution_count
FROM sys.dm_exec_cached_plans cp
CROSS APPLY sys.dm_exec_sql_text(cp.plan_handle) st
where DB_NAME(st.dbid) is not null and cp.objtype = 'proc'
group by cp.plan_handle, DB_NAME(st.dbid),
OBJECT_SCHEMA_NAME(objectid,st.dbid),
OBJECT_NAME(objectid,st.dbid)
order by max(cp.usecounts)
Currently Running Queries:
SELECT SPID,ER.percent_complete,
CAST(((DATEDIFF(s,start_time,GetDate()))/3600) as varchar) + ' hour(s), '
+ CAST((DATEDIFF(s,start_time,GetDate())%3600)/60 as varchar) + 'min, '
+ CAST((DATEDIFF(s,start_time,GetDate())%60) as varchar) + ' sec' as running_time,
CAST((estimated_completion_time/3600000) as varchar) + ' hour(s), '
+ CAST((estimated_completion_time %3600000)/60000 as varchar) + 'min, '
+ CAST((estimated_completion_time %60000)/1000 as varchar) + ' sec' as est_time_to_go,
DATEADD(second,estimated_completion_time/1000, getdate()) as est_completion_time,
ER.command,ER.blocking_session_id, SP.DBID,LASTWAITTYPE,
DB_NAME(SP.DBID) AS DBNAME,
SUBSTRING(est.text, (ER.statement_start_offset/2)+1,
((CASE ER.statement_end_offset
WHEN -1 THEN DATALENGTH(est.text)
ELSE ER.statement_end_offset
END - ER.statement_start_offset)/2) + 1) AS QueryText,
TEXT,CPU,HOSTNAME,LOGIN_TIME,LOGINAME,
SP.status,PROGRAM_NAME,NT_DOMAIN, NT_USERNAME
FROM sys.SYSPROCESSES SP
INNER JOIN sys.dm_exec_requests ER
ON sp.spid = ER.session_id
CROSS APPLY SYS.DM_EXEC_SQL_TEXT(er.sql_handle) EST
ORDER BY CPU DESC
Waiting Queries with Wait Types:
SELECT req.session_id
,blocking_session_id
,ses.host_name
,DB_NAME(req.database_id) AS DB_NAME
,ses.login_name
,req.status
,req.command
,req.start_time
,req.cpu_time
,req.total_elapsed_time / 1000.0 AS total_elapsed_time
,req.command
,req.wait_type
,sqltext.text
FROM sys.dm_exec_requests req
CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS sqltext
JOIN sys.dm_exec_sessions ses
ON ses.session_id = req.session_id
WHERE req.wait_type IS NOT NULL
SELECT DB_NAME(dbid) as DBName,
COUNT(dbid) as NumberOfConnections,
loginame as LoginName
FROM sys.sysprocesses WHERE dbid > 0
GROUP BY dbid, loginame