New Article on SQLPerformance.com comparing “Observer Overhead” of Trace vs Extended Events

I have been so busy this week that I didn’t get a chance to blog about this yesterday when it happened, but I had a new article published on SQLPerformance.com that compares the performance impact or "observer overhead" of using SQL Trace and Extended Events.  I had a lot of fun running different benchmarks for this article and the results are very revealing about the overhead associated with diagnostic data collection against SQL Server under load. 

http://www.sqlperformance.com/2012/10/sql-trace/observer-overhead-trace-extended-events

I’ll be writing additional performance related articles on SQLPerformance.com in the next few months along with other members of SQLskills so make sure you add the RSS Feed to your favorite feed reader.

How useful are query_hash and query_plan_hash for troubleshooting?

After my last post, I was contacted by email about the usefulness of query_hash in actual troubleshooting scenarios since the query_hash value is based on the statement and not the database in a system.  It just happened that the example template from SQL Server 2012 that I showed had the query_hash included in it’s definition.  The premise for the question was that Software as a Service (Saas) solutions have multiple databases, sometimes hundreds to even thousands on the same server, that have the exact same code base, so using query_hash to aggregate data is not as useful in these scenarios since the data is not guaranteed to be evenly distributed.  My first feedback on this was that my blog post didn’t actually relate any information to the query_hash action in Extended Events directly, but there happens to be more to this situation.

The query_hash and query_plan_hash provide the query finger prints in SQL Server 2008+, and simplify the effort required for analyzing adhoc/prepared workloads as well as workloads that use stored procedures in multiple databases.  To look at how to leverage this information in SaaS scenarios to identify the database that caused the most executions of the query_hash being reviewed we’ll make use of the following workload to show the accumulated effects of a specific query_hash per database.

CREATE DATABASE Test;
GO
USE Test;
GO
CREATE PROCEDURE dbo.TestProc
AS
BEGIN
    SELECT TOP 10 *
    FROM master..spt_values
    WHERE type = N’P’;
END
GO
CREATE DATABASE Test1
GO
USE Test1
GO
CREATE PROCEDURE dbo.TestProc
AS
BEGIN
    SELECT TOP 10 *
    FROM master..spt_values
    WHERE type = N’P’;
END
GO
CREATE DATABASE Test2
GO
USE Test2
GO
CREATE PROCEDURE dbo.TestProc
AS
BEGIN
    SELECT TOP 10 *
    FROM master..spt_values
    WHERE type = N’P’;
END
GO
DBCC FREEPROCCACHE;
GO

After creating the databases and objects, we’ll setup an Extended Events session to capture the statement level completed events for the session_id running the test queries and capture the query_hash to show how to use it to look at execution information per database from the query statistics in SQL Server. Since I am using SQL Server 2012, I am not using a target with the event session, but will instead capture the information using the Live Data Viewer to make it easier to show in this post.

CREATE EVENT SESSION [SQLskills_Query_Hash] ON SERVER
ADD EVENT sqlserver.sp_statement_completed(
    ACTION(sqlserver.query_hash)
    WHERE ([sqlserver].[session_id]=(66))),
ADD EVENT sqlserver.sql_statement_completed(
    ACTION(sqlserver.query_hash)
    WHERE ([sqlserver].[session_id]=(66)));

Once the session is created and started, we can run the following tests and review the output:

USE Test
GO

EXECUTE dbo.TestProc
GO 2

SELECT TOP 10 *
FROM master..spt_values
WHERE type = N’P’;
GO 5

USE Test1
GO

EXECUTE dbo.TestProc
GO 4

SELECT TOP 10 *
FROM master..spt_values
WHERE type = N’P’;
GO 7

USE Test2
GO

EXECUTE dbo.TestProc
GO 8

SELECT TOP 10 *
FROM master..spt_values
WHERE type = N’P’;
GO 3

After collecting the data, I disconnected the UI from the live stream and then grouped the events by the query_hash and summed the values for logical_reads, duration, cpu_time, and writes

image

Here we can see that all of the statements that executed had the same query_hash value, even though they were a mix of adhoc executions and procedures from different databases.  If we want to break this down to determine each databases executions we can do that by taking the query_hash value, converting it into a binary(8) data type from the bigint value produced by Extended Events, and then query sys.dm_exec_query_stats.

SELECT
    sql_handle,
    plan_handle,
    execution_count,
    total_logical_reads,
    total_elapsed_time,
    dbid,
    objectid
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) AS qp
WHERE query_hash = CONVERT(BINARY(8), CONVERT(BIGINT, 1640387627010439277));

image

Using this method we can further breakdown the information to see where our biggest impacts are.  Using the query_hash at the server level in Extended Events makes it possible to identify statements in a workload that might not have long executions but execute frequently leading to a "death by a thousand cuts".  If you need to dig into the database level information, you could add the sqlserver.database_id action to the statement level events, or just query the information out of the query statistics maintained inside of SQL Server.

Customizing Extended Events Templates in SQL Server 2012

One of the features of the Extended Events UI in SQL Server 2012 is the ability to export an event session definition out to a template for future reuse.  This can be accomplished through the right-click menu for an event session and then by selecting the Export Session menu item as shown in Figure 1.

image
Figure 1: Exporting a session

Event sessions that have been exported are saved in the %USERPROFILE%\Documents\SQL Server Management Studio\Templates\XEventTemplates path on the machine that is running SQL Server Management Studio.  When you open up a New Session Wizard or the New Session dialog to create a new event session, the templates will display the user defined templates as shown in Figure 2.

image
Figure 2: Template selection

The basic event session templates created by Management Studio can be customized to display in the UI similar to how the built-in templates display.  The built-in templates are stored in the C:\Program Files (x86)\Microsoft SQL Server\110\Tools\Templates\sql\xevent path on the client machine.  By editing one of these templates, you can grab the additional XML elements that provide the metadata about the event session template for display in the UI.  The XML from the Count Query Locks template is show below to highlight the necessary elements and their location in the XML document

<event_sessions xmlns="http://schemas.microsoft.com/sqlserver/2008/07/extendedeventsconfig">
  <event_session name="lock_counter_final" maxMemory="4" eventRetentionMode="allowSingleEventLoss" trackCausality="true" dispatchLatency="30" maxEventSize="0" memoryPartitionMode="none">
    <templateCategory>
      <!-- _locID_text="templateCategory" _locComment = "" -->Locks and Blocks</templateCategory>
    <templateName>
      <!-- _locID_text = "templateName" _locComment = "" -->Count Query Locks</templateName>
    <templateDescription>
      <!-- _locID_text = "templateDescription" _locComment = "" -->This template counts the number of locks acquired by each query based on the query_hash value. You can use this template to identify the most lock intensive queries for investigation and tuning.</templateDescription>
    <event package="sqlserver" name="lock_acquired">

The templateCategory provides the categorization in the template drop down, and the templateName provides the name that is displayed.  The templateDescription is what shows in the UI once the template is actually selected.  The comments within the XML are not required for the UI to display the information and the XML can be simplified down to:

    <templateCategory>Template Category</templateCategory>
    <templateName>Template Name</templateName>
    <templateDescription>Template Description</templateDescription>

By adding these elements manually into the session template XML between the event_session and first event elements, the UI can interpret the information for display about the template.  However, if the template resides in the user templates path, only the templateDescription element is rendered in the UI.  The templates in the user templates path all display in the UI as shown in Figure 2 above, but once selected the template description will populate as shown in Figure 3.

image

If you move the template file to the default template path, the UI will appropriately categorize the template based on the templateCategory element and will display the name in the templateName element as shown in Figure 4.

image

This shows two customized templates from the SQLskills collection of event sessions that be released as a set of templates that we’ve made use of in client work, and that I have written about in different blog posts and articles over the last three years while working with Extended Events.  Watch this blog for a final release of these templates in the near future.