Awesomesauce SQL Server 2012: System Health Session

Posted on May 8, 2012 by Amit Banerjee

There have been a spate of new features and enhancements to existing functionality in SQL Server 2012. The System Health Extended Events session is one of the benefactors. I had previously blogged about the usage of the System Health Session data using custom SSMS Reports in a four part series. Now it is time to talk about the enhancements to the System Health Session’s predecessor.

The SQL Server 2012 health session adds additional events to the default extended event health session running on the instance which is listed below to collect data for the following:

Out of memory errors for CLR and the database engine using the events:

sqlclr.clr_allocation_failure
sqlclr.clr_virtual_alloc_failure
sqlos.memory_broker_ring_buffer_recorded
sqlos.memory_node_oom_ring_buffer_recorded

Scheduler health issues using the events:

sqlos.scheduler_monitor_deadlock_ring_buffer_recorded
sqlos.scheduler_monitor_non_yielding_iocp_ring_buffer_recorded
sqlos.scheduler_monitor_non_yielding_ring_buffer_recorded
sqlos.scheduler_monitor_non_yielding_rm_ring_buffer_recorded
sqlos.scheduler_monitor_stalled_dispatcher_ring_buffer_recorded
sqlos.scheduler_monitor_system_health_ring_buffer_recorded

The results of the sp_server_diagnostics component
Security and connectivity errors encountered using the events:

sqlserver.connectivity_ring_buffer_recorded
sqlserver.security_error_ring_buffer_recorded

Additional wait types are also tracked which adds to the existing list of waits captured by this session. Since SQL Server 2012 Management Studio allows you to view the configured Extended Events session on the SQL Server 2012 instance, you can get to the system_health session using the following steps from Object Explorer (see Screenshot 1):

Expand Management –> Extended Events –> system_health.

The Script Session as option now provides you with a way to view the session definition. Another enhancement made to this session is the target for this session is now also a .xel file which by default is located in your SQL Server LOG folder. The target definition for the System Health session are now:

a. Ring Buffer (as was in SQL Server 2008)
b. XEL file – With a maximum size of 5 MB and a file retention policy of 4 files.

So now you can leverage the management studio XEvent UI to view the results. You can right-click on the ring buffer target in the UI and click on the View Target Data option which will give you an XML document.

The coolest thing that I like here is the viewer’s capability to show you all the data from all the .xel files. Once you have the events loaded, you should see a view as shown in Screenshot 2. This gives you a list of all the events that were generated. You can sort on the event columns by clicking on them. The progress of the sorting will be visible towards the top right hand corner of SSMS as shown in Screenshot 3. Now that you have the basic view, let’s find out what more can we do with the System Health Session data displayed.

You can click on the Choose Columns option in the toolbar, select the columns that you want to view additionally apart from the name and timestamp by using the Available Columns list. See Screenshot 4 for an example.

Now that you have selected the additional columns, you can also set grouping (using the Grouping button) to view each of the event name categories, the number of events reported and aggregations on the column values (using the Aggregations button). So finally, I landed up with a view as shown below in Screenshot 5. What’s more, you can save the view settings using the Display Settings button!

I am currently writing a series on SSWUG for designing SSRS reports for viewing the events reported by the System Health Session. You can following the series here. If you have SQL Server 2012 RTM installed, then you need to download the T-SQL script attached to Mike Wachal’s blog post to address the wait type information captured.

Monitoring just got a whole lot easier!!

XML Plans Saga–Breaking Dawn Part 2

Posted on April 16, 2012 by Amit Banerjee

I just completed this series and now there are four posts which points out four different ways of tracking down XML plans for troubleshooting or monitoring query performance:

XML Plans Saga –Twilight – A gist of what graphical execution plans look like.
XML Plans Saga –New Moon – Getting your hands dirty with the actual XML document representing the query plan
XML Plans Saga – Eclipse – Retrieving information about query plans using profiler trace events
XML Plans Saga – Breaking Dawn Part 1 – Fetching information from the cached plans in the SQL Server procedure cache

In this blog post (Breaking Dawn Part 2), I shall talk about the latest release in the SQL family… SQL Server 2012. With the new avatar of the Management Studio, you now have an Extended Event (XEvents) configuration wizard. Even though Extended Events have been around since SQL Server 2008, there wasn’t a wizard available for the configuration of the same. I am going to explain how XEvents can be used to capture execution plans and the existing XEvent Viewer in SQL Server 2012 Management Studio (SSMS) gives you a nice view.

I configured a XEvent trace with an asynchronous ring buffer target and captured only the query_post_execution_showplan event. The XEvent defition is shown below:

CREATE EVENT SESSION [QueryPlanCapture]
ON SERVER ADD EVENT sqlserver.query_post_execution_showplan(SET collect_database_name=(1)
ACTION(sqlos.cpu_id, sqlos.scheduler_id, sqlos.worker_address, sqlserver.database_name, sqlserver.is_system, sqlserver.nt_username, sqlserver.plan_handle, sqlserver.request_id, sqlserver.server_principal_name, sqlserver.session_id, sqlserver.session_nt_username, sqlserver.sql_text, sqlserver.transaction_id, sqlserver.tsql_frame, sqlserver.tsql_stack, sqlserver.username))
ADD TARGET package0.ring_buffer 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=ON, STARTUP_STATE=OFF)
GO

I used the Watch Live Data option in SSMS (Screenshot 1) to view the data being captured by the configured XEvent session active on the server. Now the XEvent viewer gives you a lot of options to aggregate and group data collect by the XEvent session. There are three things that I did with the GUI:

1. I first used the Choose Columns option to pick the columns that I wanted to be available in the events pane.

2. Then I picked the Grouping option to group on the object_name column value. You can only group on events which are visible in the events pane.

3. Then I picked the Aggregation option to provide me with a SUM of duration and cpu_time values for each of the event occurrences.

You can see the final output in Screenshot 2 below.

You can now see that I have all the execution plans for the execution of the stored procedure sp_helpdb. The Details pane actually gives you the option to view the graphical query plan. Another tip is that if you double-click on any of the events in the details pane, then either open up in a new pop-up window or a new query window depending on the field (eg. showplan_xml).

As you see from the Screenshot below, there is hordes of information I can pickup from the output without having to start a profiler trace. Since you get the plan_handle and the actual query plan, you can use the queries from the previous posts in the series to get the set options, missing indexes, compilation and execution statistics for the query as well. However, the aggregation option in the XEvent Viewer gives you a head start on a lot of this activity already.

Hope all of you have some fun reading these posts on XML plans and put all this info to good use in your SQL environments!

Till next time Ciao and happy query plan spotting!!

System Health Session: Part 4

Posted on September 28, 2011 by Amit Banerjee

This is the last post for the System Health Session series. In this post, I shall show you how to extract deadlock related information from the deadlock graph captured by the System Health Session.

The deadlock graph captured typically has three distinct nodes:

victim-list – Deadlock victim’s process identifier
process-list – Information pertaining to all the processes involved in the deadlock
resource-list – Information about the resources involved in the deadlock

The query below will provide you with the time stamp when the deadlock was reported along with victim process identifier.

 -- Fetch the Health Session data into a temporary table

SELECT CAST(xet.target_data AS XML) AS XMLDATA
INTO #SystemHealthSessionData
FROM sys.dm_xe_session_targets xet
JOIN sys.dm_xe_sessions xe
ON (xe.address = xet.event_session_address)
WHERE xe.name = 'system_health'
-- Gets the Deadlock Event Time and Victim Process
SELECT C.query('.').value('(/event/@timestamp)[1]', 'datetime') as EventTime,
CAST(C.query('.').value('(/event/data/value)[1]', 'varchar(MAX)') AS XML).value('(<a>/deadlock/victim-list/victimProcess/@id)[1]','varchar(100)'</a>) VictimProcess
FROM #SystemHealthSessionData a
CROSS APPLY a.XMLDATA.nodes('/RingBufferTarget/event') as T(C)
WHERE C.query('.').value('(/event/@name)[1]', 'varchar(255)') = 'xml_deadlock_report'
-- Drop the temporary table
DROP TABLE #SystemHealthSessionData

The next query (when provided with an event time from the above query output)
will provide you a parsed version of the process list in a tabular format which
can be easier to read when you have a large number of sessions involved in the
deadlock.

 -- Fetch the Health Session data into a temporary table

SELECT CAST(xet.target_data AS XML) AS XMLDATA
INTO #SystemHealthSessionData
FROM sys.dm_xe_session_targets xet
JOIN sys.dm_xe_sessions xe
ON (xe.address = xet.event_session_address)
WHERE xe.name = 'system_health'

-- Parses the process list for a specific deadlock once provided with an event time for the deadlock from the above output

;WITH CTE_HealthSession (EventXML) AS
(
SELECT CAST(C.query('.').value('(/event/data/value)[1]', 'varchar(MAX)') AS XML) EventXML
FROM #SystemHealthSessionData a
CROSS APPLY a.XMLDATA.nodes('/RingBufferTarget/event') as T(C)
WHERE C.query('.').value('(/event/@name)[1]', 'varchar(255)') = 'xml_deadlock_report'
AND C.query('.').value('(/event/@timestamp)[1]', 'datetime') = '2011-09-28 06:24:44.700' -- Replace with relevant timestamp
)
SELECT DeadlockProcesses.value('(@id)[1]','varchar(50)') as id
,DeadlockProcesses.value('(@taskpriority)[1]','bigint') as taskpriority
,DeadlockProcesses.value('(@logused)[1]','bigint') as logused
,DeadlockProcesses.value('(@waitresource)[1]','varchar(100)') as waitresource
,DeadlockProcesses.value('(@waittime)[1]','bigint') as waittime
,DeadlockProcesses.value('(@ownerId)[1]','bigint') as ownerId
,DeadlockProcesses.value('(@transactionname)[1]','varchar(50)') as transactionname
,DeadlockProcesses.value('(@lasttranstarted)[1]','varchar(50)') as lasttranstarted
,DeadlockProcesses.value('(@XDES)[1]','varchar(20)') as XDES
,DeadlockProcesses.value('(@lockMode)[1]','varchar(5)') as lockMode
,DeadlockProcesses.value('(@schedulerid)[1]','bigint') as schedulerid
,DeadlockProcesses.value('(@kpid)[1]','bigint') as kpid
,DeadlockProcesses.value('(@status)[1]','varchar(20)') as status
,DeadlockProcesses.value('(@spid)[1]','bigint') as spid
,DeadlockProcesses.value('(@sbid)[1]','bigint') as sbid
,DeadlockProcesses.value('(@ecid)[1]','bigint') as ecid
,DeadlockProcesses.value('(@priority)[1]','bigint') as priority
,DeadlockProcesses.value('(@trancount)[1]','bigint') as trancount
,DeadlockProcesses.value('(@lastbatchstarted)[1]','varchar(50)') as lastbatchstarted
,DeadlockProcesses.value('(@lastbatchcompleted)[1]','varchar(50)') as lastbatchcompleted
,DeadlockProcesses.value('(@clientapp)[1]','varchar(150)') as clientapp
,DeadlockProcesses.value('(@hostname)[1]','varchar(50)') as hostname
,DeadlockProcesses.value('(@hostpid)[1]','bigint') as hostpid
,DeadlockProcesses.value('(@loginname)[1]','varchar(150)') as loginname
,DeadlockProcesses.value('(@isolationlevel)[1]','varchar(150)') as isolationlevel
,DeadlockProcesses.value('(@xactid)[1]','bigint') as xactid
,DeadlockProcesses.value('(@currentdb)[1]','bigint') as currentdb
,DeadlockProcesses.value('(@lockTimeout)[1]','bigint') as lockTimeout
,DeadlockProcesses.value('(@clientoption1)[1]','bigint') as clientoption1
,DeadlockProcesses.value('(@clientoption2)[1]','bigint') as clientoption2
FROM (select EventXML as DeadlockEvent FROM CTE_HealthSession) T
CROSS APPLY DeadlockEvent.nodes('//deadlock/process-list/process') AS R(DeadlockProcesses)

-- Drop the temporary table
DROP TABLE #SystemHealthSessionData

The script file for the above queries can be downloaded from here.

A sample output of the above two queries is shown below:

The second dataset which shows the parsed process list from the deadlock graph is for the timestamp highlighted above.

As mentioned in one of my previous posts, the custom reports used in the previous posts can be downloaded from here (Filename: System_Health_Session_Custom_Reports.zip).

Modification April 20th, 2012: Just updated the .sql files and added the Deadlock Report to the SkyDrive location.

Note: To make use of the deadlock graph captured by the System Health Session, you need to have the required update applied to avoid the issue mentioned in KB978629. The issue is addressed in:
981355 Cumulative Update package 1 for SQL Server 2008 R2
http://support.microsoft.com/default.aspx?scid=kb;EN-US;981355
977443 Cumulative update package 6 for SQL Server 2008 Service Pack 1
http://support.microsoft.com/default.aspx?scid=kb;EN-US;977443

If you don’t have the updates installed, then Jonathan (Blog | Twitter) has shown in his article Retrieving Deadlock Graphs with SQL Server 2008 Extended Events how to workaround the issue. Michael Zilberstein’s (Blog) article, Parsing Extended Events xml_deadlock_report, has an updated/corrected version of the T-SQL to fetch the deadlock information.

References:

Bart Duncan’s Weblog:
Deadlock Troubleshooting, Part 1
Deadlock Troubleshooting, Part 2
Deadlock Troubleshooting, Part 3

del.icio.us Tags: Extended Events,Monitoring,SQL Server 2008,SQL Server 2008
R2,system_health session

System Health Session: Part 3

Posted on September 28, 2011 by Amit Banerjee

In my last post, I had demonstrated how to fetch the waits information captured by the System Health session. In this post, I shall show the custom reports that can be built using the waits information fetched.

The above report gives a summary of all the waits recorded by the health session. I have a second level drill-down available which allows me to get specific information for each of the distinct waits reported above and lets me get the SQL Query that experienced the wait.

As you can see above, that I have the SQL query, the time when the wait was reported along with duration statistics of the wait.

Another category of events that are tracked by the System Health session are non-yielding scheduler conditions (reported using the error number 17883) in SQL Server. So if your SQL Server instance encountered a non-yielding scheduler condition, then this information can be tracked using System Health session. The query below will give you the information of all the non-yielding conditions detected by the SQL Server instance subject to condition that the ring buffer storing this information has not been overwritten.

-- Query to fetch non-yielding errors captured by the System Health Session
SET NOCOUNT ON

SELECT CAST(xet.target_data AS XML) AS XMLDATA
INTO #SystemHealthSessionData
FROM sys.dm_xe_session_targets xet
JOIN sys.dm_xe_sessions xe ON (xe.address = xet.event_session_address)
WHERE xe.name = 'system_health'

;WITH CTE_HealthSession (EventXML) AS
( SELECT C.query('.') EventXML
FROM #SystemHealthSessionData a
CROSS APPLY a.XMLDATA.nodes('/RingBufferTarget/event') as T(C)
WHERE C.query('.').value('(/event/@name)[1]', 'varchar(255)') = 'scheduler_monitor_non_yielding_ring_buffer_recorded' )
SELECT EventXML.value('(/event/@timestamp)[1]', 'datetime') as EventTime,
EventXML.value('(/event/data/value)[4]', 'int') as NodeID,
EventXML.value('(/event/data/value)[5]', 'int') as SchedulerID,
CASE EventXML.value('(/event/data/value)[3]', 'int') WHEN 0 THEN 'BEGIN' WHEN 1 THEN 'END' ELSE '' END AS DetectionStage,
EventXML.value('(/event/data/value)[6]', 'varchar(50)') as Worker,
EventXML.value('(/event/data/value)[7]', 'bigint') as Yields,
EventXML.value('(/event/data/value)[8]', 'int') as Worker_Utilization,
EventXML.value('(/event/data/value)[9]', 'int') as Process_Utilization,
EventXML.value('(/event/data/value)[10]', 'int') as System_Idle,
EventXML.value('(/event/data/value)[11]', 'bigint') as User_Mode_Time,
EventXML.value('(/event/data/value)[12]', 'bigint') as Kernel_Mode_Time,
EventXML.value('(/event/data/value)[13]', 'bigint') as Page_Faults,
EventXML.value('(/event/data/value)[14]', 'float') as Working_Set_Delta,
EventXML.value('(/event/data/value)[15]', 'bigint') as Memory_Utilization
FROM CTE_HealthSession
ORDER BY EventTime,Worker

DROP TABLE #SystemHealthSessionData

The .sql file for the above script is available here.

A sample output of the above query is shown on the left. An important information in this output is the worker address. Using this worker address, I can get the relevant messages pertaining to the non-yielding condition.

2011-09-27 21:57:51.560 Server       Process 0:0:0 (0x18c0) Worker 0x000000000606A1A0 appears to be non-yielding on Scheduler 5. Thread creation time: 12961597452926. Approx Thread CPU Used: kernel 0 ms, user 0 ms. Process Utilization 0%. System Idle 98%. Interval: 70077 ms.
2011-09-27 21:58:51.660 Server       Process 0:0:0 (0x18c0) Worker 0x000000000606A1A0 appears to be non-yielding on Scheduler 5. Thread creation time: 12961597452926. Approx Thread CPU Used: kernel 0 ms, user 0 ms. Process Utilization 0%. System Idle 97%. Interval: 133017 ms.
2011-09-27 21:59:51.760 Server       Process 0:0:0 (0x18c0) Worker 0x000000000606A1A0 appears to be non-yielding on Scheduler 5. Thread creation time: 12961597452926. Approx Thread CPU Used: kernel 0 ms, user 0 ms. Process Utilization 2%. System Idle 94%. Interval: 193116 ms.
2011-09-27 22:00:51.860 Server       Process 0:0:0 (0x18c0) Worker 0x000000000606A1A0 appears to be non-yielding on Scheduler 5. Thread creation time: 12961597452926. Approx Thread CPU Used: kernel 0 ms, user 0 ms. Process Utilization 3%. System Idle 93%. Interval: 253215 ms.

If you look at the Errorlog snippet above, you will notice that there are entries for the highlighted worker address are same as the one reported in the management studio output screen shot above. The time reported in the Errorlog is the server time (in my case it is UTC+5:30) where as the time stamps reported by the health session is UTC time which means that the timestamps reported also match. Using the events from the System Health Session and the Errorlog entries, I will be able to figure out when a non-yielding condition occurred on the server instance.

The non-yielding condition report is quite plain and has a table output showing the different columns returned by the query above:

In the last post for this series, I shall provide the set of queries that can be used to parse a deadlock graph collected by the System Health session along with the .rdl files for the custom reports used in this series.

del.icio.us Tags: Extended Events,Monitoring,SQL Server 2008,SQL Server 2008 R2,system_health session

System Health Session: Part 2

Posted on September 23, 2011 by Amit Banerjee

I had written an introductory post on monitoring the system health using the default extended events sessions that runs on a SQL Server 2008 instance and above. Now it is time for next part for this post. In the first post, I provided a set of queries which would be used for getting all the errors that were recorded by the System Health Extended Events session. Now I can create a set of reports using Business Intelligence Development Studio which can be used by the Custom Reports feature of Management Studio.

I put together a three-level drill down report to get a summary report for all the errors reported by the T-SQL queries in my previous post. The dashboard report which will basically serve as the landing page for what I am terming as the System Health Dashboard looks something like this:

As you can see above, the report shows me the different events captured by the Extended Events session. The first level drill down provides a summary of all the different errors reported.

The last drill-down option is to go look into every occurrence of a specific error number. This report basically shows all the occurrences of a specific error number along with the query text (if captured) and specifics for the event recorded rather than the generic error description that you see in the above report.

The other category of events captured by the Health Session are wait information which fall under the following category:

Any sessions that have waited on latches (or other interesting resources) for > 15 seconds.
Any sessions that have waited on locks for > 30 seconds.
Any sessions that have waited for a long time for preemptive waits. The duration varies by wait type. A preemptive wait is where SQL Server is waiting for external API calls.

The query below will give you the query which experienced the wait along with the wait times which were recorded by the System Health session.

SELECT CAST(xet.target_data AS XML) AS XMLDATA

INTO #SystemHealthSessionData

FROM sys.dm_xe_session_targets xet

JOIN sys.dm_xe_sessions xe

ON (xe.address = xet.event_session_address)

WHERE xe.name = 'system_health'

;WITH CTE_HealthSession (EventXML) AS

(

SELECT C.query('.') EventXML

FROM #SystemHealthSessionData a

CROSS APPLY a.XMLDATA.nodes('/RingBufferTarget/event') as T(C)

WHERE C.query('.').value('(/event/@name)[1]', 'varchar(255)') in ('wait_info','wait_info_external')

)

SELECT

EventXML.value('(/event/@timestamp)[1]', 'datetime') as EventTime,

EventXML.value('(/event/data/text)[1]', 'varchar(50)') as WaitType,

EventXML.value('(/event/data/value)[3]', 'int') as Duration,

EventXML.value('(/event/data/value)[4]', 'int') as Max_Duration,

EventXML.value('(/event/data/value)[5]', 'int') as Total_Duration,

EventXML.value('(/event/action/value)[2]', 'varchar(10)') as Session_ID,

EventXML.value('(/event/action/value)[3]', 'varchar(max)') as sql_text

FROM CTE_HealthSession

ORDER BY EventTime DESC

DROP TABLE #SystemHealthSessionData

A sample output of the above query is shown above. The .sql file for the above query can be downloaded from here.

Note: Beware of false positives for PREEMPTIVE_OS_GETPROCADDRESS waits described here.

In the next post, I shall give a preview of the wait reports and provide another set of queries to track a category of events tracked by the System Health session.

Once I have completed this series, I shall upload all the series of reports to my SkyDrive so that they can be downloaded for your benefit.

del.icio.us Tags: Extended Events,Monitoring,SQL Server 2008,SQL Server 2008 R2,system_health session