SQL Server 2014 Extended Events
This article will focus on how using SQL Server 2014 Extended Events can be used to troubleshoot query performance. It is not meant as a complete tutorial of how to use Extended Events, rather a demonstration.
SQL Server 2014 Extended Events is not necessarily a new feature of SQL Server. In fact it has been part of the database engine since SQL Server 2008 and improving with each major release. However, I suspect not many DBAs know or use it over traditional tools such as Profiler. Depending on what you read online, Profiler will eventually be deprecated and replaced by Extended Events (note, as of SQL Server 2014 Profiler is still integrated with Activity Monitor and SQLDiag, so this change seems to be slow). Perhaps part of the issue for DBAs not migrating towards Extended Events may be usability. Starting with SQL Server 2012, Microsoft has integrated a new user interface into Management Studio.
If you’re familiar with Profiler, some of Extended Events will be familiar to you. In fact, you can convert your favorite Trace script to an Extended Events session. However, the user interface for Extended Events is completely different and will require some time getting familiar with it. Extended Events offers many more events than Profiler and increased configurability.
In the example scenario below, I have created a situation to simulate a deadlock in the AdventureWorks2014 database. I’ll attempt to demonstrate in this post how using Extended Events can help get gather information to troubleshoot the issue. To configure this test scenario, I created two sessions connected to a SQL Server 2014 instance. The first session, SPID 56, is executing a transaction while the second session, SPID 57, is running another transaction using some of the same database objects. I configured a custom Extended Events session to capture various events while these database transactions execute.
One benefit of Extended Events over Profiler is that is does not require a new connection an runs in the background requiring less overhead and minimally impacting your server. Viewing the process state in Activity Monitor, we can see that process 56 is blocked by process 57. You’ll notice that there is not a separate process for Extended Events. Launching the standard “Trace process in SQL Server Profiler” option from Activity Monitor for SPID 57 reveals a new process created with SPID 53.
Built-in templates help get you started with a set of events. There is also a wizard to quickly configure a session. When using templates, some customization is helpful to add and/or remove certain events from the ones selected in the template. Additionally, some events may need to be configured further to capture the data you need to add additional information and to set filters. In this example, I started a new session and selected the “Query Detail Tracking” template to start with. I further customized and added additional Events for demonstration purposes. The Selected Events list now looks like this:
The events can be further configured to add additional detail and filters by selecting the “Configure” button. I found that one of the more useful fields to add to each event is the “session_id”. This takes a few extra minutes, but this is extremely useful when filtering the final Extended Events session log. Aside from configuring events, I often also change or add the “Data Storage” target under “Session Properties”. By default on several templates, the “ring buffer” target is set. I generally set the target to an output file, “event_file”.
In my test scenario, I started my new Extended Events session while my test transactions were executing. Once the transactions completed I stopped the session to prevent additional collection. Since there were over 4 million entries in the session I created, a filter can be added to the results. I decided to add a filter on SPID 57 using the session_id field and then group the events by Event Name. This is useful for drilling down to the events associated with this specific process and ignoring everything else that was running at the time. In addition to the filter, I also grouped the results by event. The Event File now looks like the following:
The filter helped reduce the amount of information. However, because of my scenario, there are still a lot of entries. Note, this is expected, because I created a large while loop executing the same command repeatedly. This explains why there were a lot of entries for some of these events. Typically, filtering will generate a much more concise result set. To demonstrate how to use this information I’ll focus on the “error_reported” event. Because of the amount of information, I added an additional filter on this specific event, to exclude any informational messages.
The Event File output has now been filtered on event “error_reported” for SPID 57 and contains only errors with a severity greater than 10. I’m able to determine that SPID 57 failed when attempting to insert a value and generated a Foreign Key constraint error. I also have the SQL that was executed. Double-clicking any of the Details fields will create a pop-up window showing the complete text.
Notice, that there are still over 18,000 entries. I can continue to use filtering to exclude the Insert error. With this additional filter I’m able to conclude that all of these entries are reporting the same error and move on with additional analysis.
Extended Event System Health
Let us assume that SPID 56 is executed from an application and the user complained their process never completed and received a deadlock error. Using the built-in Extended Event System Health session I can check for any deadlock information. After grouping the events, I noticed that there is an entry in the “xml_deadlock_report” event.
This information is viewable as XML or graphical. Double-clicking the XML details will automatically open it in SSMS under a new query window. Using the graphical view, I’m able to view information about the deadlock.
After some investigation, I can conclude that the insert statement or transaction executed by SPID 57 caused SPID 56 to deadlock. SPID 56 was executing a select statement at the time of the deadlock. The deadlock occurred because both processes were accessing the same table, Person.Person. To view the query plan of the two statements I need to switch back to the Extended Events session I created and go to the “query_pre_execution_showplan” event. This event provides a nice way to capture the XML showplan and the graphical Query Plan. An example of this is shown below.
As in real world scenarios and in this particular test scenario, it can be difficult to determine root causes for deadlocks. Using the Extended Events information, there was useful information regarding lock types, database objects involved and error messages. We discovered that there were no red flags after investigating the blocked process report and query plans of the SQL statements. We do have information that can help guide us to find the root cause. The type of information that could be sent to a developer would be the following:
- Lock information that shows Page locks on the Person.Person table in database AdventureWorks2014.
- Error information captured from the Extended Event sessions for both SPIDs
- The deadlock error generated by SPID 56
- The FK insert error generated by SPID 57
- Performance tuning insights gained from analyzing the query plans of SPID 56 and 57.
- The actual SQL text of the transaction executed by SPID 57. Using the information contained in the sql_text details we can determine that there may be transaction mismanagement. There appears to be two “begin transaction” statements and only one “commit transaction” statement.
Using Extended Events is a lightweight method in capturing detailed SQL Server data. Sessions can be configured and run for short periods of time. Given the fact that Microsoft is planning to replace Profile with Extended Events, it is a good idea to get familiar with it.