SQL Server – Capture Long Running Stored Procedures and Execution Count using Extended Events

I always use SQL profiler to capture query performance. I’ve read about Extended Events somewhere but I just don’t use it because I’m just too comfortable using SQL profiler. Then one day, I attended a SQL Server User Group session. The speaker talked about Extended Events and encouraged us to use it because of the following reasons:

  • SQL profiler will be deprecated.
  • Extended events less resource-intensive.
  • There are a lot of enhancements done to the extended events since it was introduced. On the other hand, SQL profiler has not been enhanced for a long time.
  • Extended events is easier to use.

After listening to the presentation, I was inspired to use Extended Events.

Below is how I use it to capture Query Performance.

1. Create extended event to capture query performance. Indicate the username and DatabaseName that you want to monitor.

CREATE EVENT SESSION [QueryPerformance] ON SERVER 

ADD EVENT sqlserver.rpc_completed(SET collect_statement=(1)

    ACTION(sqlserver.database_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)

    WHERE ([sqlserver].[equal_i_sql_unicode_string]([sqlserver].[username],N'username') AND [sqlserver].[equal_i_sql_unicode_string]([sqlserver].[database_name],N'DatabaseName') AND [duration]>=(500000))),

ADD EVENT sqlserver.sql_batch_completed(

    ACTION(sqlserver.database_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)

    WHERE ([sqlserver].[equal_i_sql_unicode_string]([sqlserver].[username],N' username ') AND [sqlserver].[equal_i_sql_unicode_string]([sqlserver].[database_name],N'DatabaseName') AND [duration]>=(500000))) 

ADD TARGET package0.event_file(SET filename=N'D:\DBA\ExtendedEvents\QueryPerformance\QueryPerformance.xel')

WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)

GO


2. Start extended event (Session Name: QueryPerformance)

To start extended event session via T-SQL:

ALTER EVENT SESSION [QueryPerformance] 
ON SERVER STATE = START 

3. Stop Extended Events.

Via T-SQL:

ALTER EVENT SESSION [QueryPerformance] 
ON SERVER STATE = STOP

Note: We can schedule Extended Events Session Start or Stop by creating SQL Agent Jobs. You may refer to this link https://www.concurrency.com/blog/december-2015/schedule-extended-events-session-start-or-stop

Now, a file has been generated in your server.

4. Load the data captured from extended events to a table. Preferrably to a utility database. Execute the script below on your utility database. You may change the name of the target table where you want to load the data captured.

WITH xEvents
AS (SELECT object_name AS xEventName,
CAST (event_data AS XML) AS xEventData
FROM sys.fn_xe_file_target_read_file('D:\DBA\ExtendedEvents\QueryPerformance\QueryPerformance*.xel',
NULL, NULL, NULL)
)
SELECT xEventName,
xEventData.value('(/event/data[@name=''duration'']/value)[1]','bigint') Duration,
xEventData.value('(/event/data[@name=''physical_reads'']/value)[1]','bigint') PhysicalReads,
xEventData.value('(/event/data[@name=''logical_reads'']/value)[1]','bigint') LogicalReads,
xEventData.value('(/event/data[@name=''cpu_time'']/value)[1]','bigint') CpuTime,
CASE xEventName
 WHEN 'sql_batch_completed'
 THEN xEventData.value('(/event/data[@name=''batch_text'']/value)[1]',
 'varchar(max)')
 WHEN 'rpc_completed'
 THEN xEventData.value('(/event/data[@name=''statement'']/value)[1]',
 'varchar(max)')
END AS SQLText,
xEventData.value('(/event/data[@name=''object_name'']/value)[1]','varchar(max)') Object_Name
INTO Table_Name
FROM xEvents;
 


5. Execute the script below to get the Stored Procedure names and their run duration and total execution count.

SELECT 
 Object_name,
 MIN(st.Duration)/1000 AS MIN_Duration_ms,
 AVG(st.Duration)/1000 AS AVG_Duration_ms,
 MAX(st.Duration)/1000 AS MAX_Duration_ms,
 COUNT(*) AS TotalExecutions
FROM Table_Name AS st
GROUP BY   Object_name
ORDER BY AVG(st.Duration) DESC;

Note: The duration captured from extended events is in microseconds. That is why in my script, I divided it by 1000 to convert it to milliseconds (ms). It is easier to read in ms.

Knowledge worth sharing...Share on linkedin
Linkedin
Share on facebook
Facebook
Share on google
Google
Share on twitter
Twitter

SQL Server – Top Queries Consuming CPU

Below is a script that captures that top SQL queries consuming CPU.

SELECT TOP 50
[Avg. MultiCore/CPU time(sec)] = qs.total_worker_time / 1000000 / qs.execution_count,
[Total MultiCore/CPU time(sec)] = qs.total_worker_time / 1000000,
[Avg. Elapsed Time(sec)] = qs.total_elapsed_time / 1000000 / qs.execution_count,
[Total Elapsed Time(sec)] = qs.total_elapsed_time / 1000000,
qs.execution_count,
[Avg. I/O] = (total_logical_reads + total_logical_writes) / qs.execution_count,
[Total I/O] = total_logical_reads + total_logical_writes,
Query = SUBSTRING(qt.[text], (qs.statement_start_offset / 2) + 1,
(
(
CASE qs.statement_end_offset
WHEN -1 THEN DATALENGTH(qt.[text])
ELSE qs.statement_end_offset
END - qs.statement_start_offset
) / 2
) + 1
),
Batch = qt.[text],
[DB] = DB_NAME(qt.[dbid]),
qs.last_execution_time,
qp.query_plan
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_sql_text(qs.[sql_handle]) AS qt
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) AS qp
where qs.execution_count > 5 --more than 5 occurences
ORDER BY [Total MultiCore/CPU time(sec)] DESC

SQL Server – Setup SQL Profiler to Capture Costly Queries / Stored Procedures

  • Click Tools >​​ SQL Server Profiler

 

 

 

  • Connect to the instance

 

 

 

  • On this page, perform the following:

    • Indicate​​ Trace name

    • Choose ​​ “Tuning” template

    • Save to file

    • Set​​ 1000​​ maximum file size

    • Set trace stop time (optional. You may stop the trace anytime)

 

 

 

  • Go to​​ Events​​ Selection​​ tab

C:\Users\Ricky\AppData\Local\Temp\SNAGHTML4fc4102.PNG

 

 

  • Tick​​ Show all columns​​ and choose the following columns

 

 

 

  • Click​​ Column Filters

 

 

 

 

 

  • Filter​​ DatabaseName​​ and​​ Duration​​ (>= 500ms)

 

 

 

  • Click​​ Run

 

SQL SERVER – LCK_M_XXX – Wait Type

Locking is a mechanism used by the SQL Server Database Engine to synchronize access by multiple users to the same piece of data, at the same time. In simpler words, it maintains the​​ integrity of data by protecting (or preventing) access to the database object.

 

LCK_M_BU
Occurs when a task is waiting to acquire a Bulk Update (BU) lock.

 

LCK_M_IS
Occurs when a task is waiting to acquire an Intent Shared (IS) lock.

 

LCK_M_IU
Occurs when a​​ task is waiting to acquire an Intent Update (IU) lock.

 

LCK_M_IX
Occurs when a task is waiting to acquire an Intent Exclusive (IX) lock.

 

LCK_M_S
Occurs when a task is waiting to acquire a Shared lock.

 

LCK_M_SCH_M
Occurs when a task is waiting to acquire a Schema Modify lock.

 

LCK_M_SCH_S
Occurs when a task is waiting to acquire a Schema Share lock.

 

LCK_M_SIU
Occurs when a task is waiting to acquire a Shared With Intent Update lock.

 

LCK_M_SIX
Occurs when a task is waiting to acquire a Shared With Intent Exclusive lock.

 

LCK_M_U
Occurs when a task is waiting to acquire an Update lock.

 

LCK_M_UIX
Occurs when a task is waiting to acquire an Update With Intent Exclusive lock.

 

LCK_M_X
Occurs when a task is waiting to acquire an Exclusive lock.

 

SQL Server – Pending Disk IO Count

Below is a script to see the number of pending disk IO. The ideal value is 0.​​ This value indicates the number of pending I/Os that are waiting to be completed. Each scheduler has a list of pending I/Os that are checked to determine whether they have been completed every time there is a context switch. The count is incremented when the request is inserted. This count is decremented when the request is completed.

 

 

SELECT​​ SUM(pending_disk_io_count)​​ AS​​ [Number of pending I/Os]​​ 

FROM​​ sys.dm_os_schedulers

 

 

SQL Server – DMV to View Missing Indexes

--DMV to view missing indexes

SELECT​​ 

*

FROM​​ 

sys.dm_db_missing_index_group_stats​​ AS​​ igs

JOIN​​ 

sys.dm_db_missing_index_groups​​ AS​​ ig​​ ON​​ igs.group_handle​​ =​​ ig.index_group_handle

JOIN​​ 

sys.dm_db_missing_index_details​​ AS​​ id​​ ON​​ ig.index_handle​​ =​​ id.index_handle

 

SQL Server – Get List of Index Information

-- Ensure a USE ​​ statement has been executed first.

SELECT​​ [DatabaseName]

 ​​ ​​ ​​​​ ,[ObjectId]

 ​​ ​​ ​​​​ ,[ObjectName]

 ​​ ​​ ​​​​ ,[IndexId]

 ​​ ​​ ​​​​ ,[IndexDescription]

 ​​ ​​ ​​​​ ,CONVERT(DECIMAL(16,​​ 1),​​ (SUM([avg_record_size_in_bytes]​​ *​​ [record_count])​​ /​​ (1024.0​​ *​​ 1024)))​​ AS​​ [IndexSize(MB)]

 ​​ ​​ ​​​​ ,[lastupdated]​​ AS​​ [StatisticLastUpdated]

 ​​ ​​ ​​​​ ,[AvgFragmentationInPercent]

FROM​​ (

 ​​ ​​ ​​​​ SELECT​​ DISTINCT​​ DB_Name(Database_id)​​ AS​​ 'DatabaseName'

 ​​ ​​ ​​ ​​ ​​ ​​ ​​​​ ,OBJECT_ID​​ AS​​ ObjectId

 ​​ ​​ ​​ ​​ ​​ ​​ ​​​​ ,Object_Name(Object_id)​​ AS​​ ObjectName

 ​​ ​​ ​​ ​​ ​​ ​​ ​​​​ ,Index_ID​​ AS​​ IndexId

 ​​ ​​ ​​ ​​ ​​ ​​ ​​​​ ,Index_Type_Desc​​ AS​​ IndexDescription

 ​​ ​​ ​​ ​​ ​​ ​​ ​​​​ ,avg_record_size_in_bytes

 ​​ ​​ ​​ ​​ ​​ ​​ ​​​​ ,record_count

 ​​ ​​ ​​ ​​ ​​ ​​ ​​​​ ,STATS_DATE(object_id,​​ index_id)​​ AS​​ 'lastupdated'

 ​​ ​​ ​​ ​​ ​​ ​​ ​​​​ ,CONVERT([varchar](512),​​ round(Avg_Fragmentation_In_Percent,​​ 3))​​ AS​​ 'AvgFragmentationInPercent'

 ​​ ​​ ​​​​ FROM​​ sys.dm_db_index_physical_stats(db_id(),​​ NULL,​​ NULL,​​ NULL,​​ 'detailed')

 ​​ ​​ ​​​​ WHERE​​ OBJECT_ID​​ IS​​ NOT​​ NULL

 ​​ ​​ ​​ ​​ ​​ ​​ ​​​​ AND​​ Avg_Fragmentation_In_Percent​​ <>​​ 0

 ​​ ​​ ​​​​ )​​ T

GROUP​​ BY​​ DatabaseName

 ​​ ​​ ​​​​ ,ObjectId

 ​​ ​​ ​​​​ ,ObjectName

 ​​ ​​ ​​​​ ,IndexId

 ​​ ​​ ​​​​ ,IndexDescription

 ​​ ​​ ​​​​ ,lastupdated

 ​​ ​​ ​​​​ ,AvgFragmentationInPercent

ORDER​​ BY​​ AvgFragmentationInPercent​​ DESC

 

 

SQL Server – View Fragmentation Level

SELECT​​ 

OBJECT_NAME(ix.OBJECT_ID)​​ AS​​ TableName,​​ 

ix.name​​ AS​​ IndexName,​​ 

ixs.index_type_desc​​ AS​​ IndexType,​​ 

ixs.avg_fragmentation_in_percent​​ 

FROM​​ 

sys.dm_db_index_physical_stats(DB_ID(),​​ NULL,​​ NULL,​​ NULL,​​ NULL)​​ ixs​​ 

INNER​​ JOIN​​ 

sys.indexes​​ ix​​ ON​​ ix.object_id​​ =​​ ixs.object_id​​ AND​​ ixs.index_id​​ =​​ ixs.index_id​​ 

WHERE​​ 

ixs.avg_fragmentation_in_percent​​ >​​ 30​​ 

ORDER​​ BY​​ 

ixs.avg_fragmentation_in_percent​​ DESC

 

SQL Server – TOP 5 Queries with Avg CPU Time

SELECT​​ TOP​​ 5​​ total_worker_time/execution_count​​ AS​​ [Avg CPU Time],​​ 

 ​​​​ SUBSTRING(st.text,​​ (qs.statement_start_offset/2)+1,

 ​​ ​​ ​​ ​​​​ ((CASE​​ qs.statement_end_offset

 ​​ ​​ ​​ ​​​​ WHEN​​ -1​​ THEN​​ DATALENGTH(st.text)

 ​​ ​​ ​​ ​​​​ ELSE​​ qs.statement_end_offset

 ​​ ​​ ​​ ​​​​ END​​ -​​ qs.statement_start_offset)/2)​​ +​​ 1)​​ AS​​ statement_text

FROM​​ sys.dm_exec_query_stats​​ AS​​ qs

CROSS​​ APPLY​​ sys.dm_exec_sql_text(qs.sql_handle)​​ AS​​ st

ORDER​​ BY​​ total_worker_time/execution_count​​ DESC;

 

SQL Server – Identifying Current Running Queries with Database Name

Use the script below to get the current running queries on your server.

SELECT 
sqltext.TEXT
,DB_Name(req.database_id) as DatabaseName
,sess.last_request_start_time 
,req.total_elapsed_time/1000 as total_elapsed_time
,sess.session_id AS SessionID 
,req.blocking_session_id AS BlockedBy
,req.command
,req.cpu_time AS CPU_Time 
,sess.HOST_NAME as RunningFrom 
,sess.login_name 
,wait_type
,wait_time
,sess.status 
,req.reads 
,req.writes 
,req.logical_reads 
,sess.program_name
FROM 
sys.dm_exec_requests req 
INNER JOIN sys.dm_exec_sessions sess ON sess.session_id = req.session_id      
AND sess.is_user_process = 1 
CROSS APPLY 
sys.dm_exec_sql_text(sql_handle) AS sqltext
WHERE DB_Name(req.database_id) NOT IN ('master','tempdb')
ORDER BY total_elapsed_time DESC