New Article: Tracking Database File AutoGrowth with Event Notifications

My latest article on SQL Server Central was published live today.  This article shows how to use Event Notifications to monitor and alert on database file auto growth events inside of SQL Server and is another edition to the series I committed to writing on using Event Notifications in SQL Server to automate common DBA tasks

http://www.sqlservercentral.com/articles/autogrowth/93229/

Look for another article in the series in the future.  Enjoy!

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

How useful are query hash and query plan hash for troubleshooting?   image thumb

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));

How useful are query hash and query plan hash for troubleshooting?   image thumb

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.

Customizing Extended Events Templates in SQL Server 2012   image thumb
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.

Customizing Extended Events Templates in SQL Server 2012   image thumb
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.

Customizing Extended Events Templates in SQL Server 2012   image thumb

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.

Customizing Extended Events Templates in SQL Server 2012   image thumb

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.

Announcing the SQLskills Availability Group Demonstrator

This spring at SQL Connections, I presented a pre-conference seminar with Kimberly on the new features in SQL Server 2012, including Availability Groups.  While on my flight to Las Vegas, I was working on an application in C# that motivated me to write a new demonstrator application for use with Availability Groups.  I spent a little time putting together a small application that I have used for every Availability Group demonstration since, and I’ve been asked a few times if I would make the application publicly available.  Paul and I discussed this and agreed that we’d offer the application as a free download.

The application is really simple in its design and usage, so I am going to use this post to show how to configure the application as well as how to use it for demonstrations of Availability Groups, or just to play with all the features provided by Availability Groups during your own testing.

Application Configuration Options

The application uses a basic application configuration file that most .NET applications use.  The configuration file is really simple and provides the ability to customize the defaults that are available in the New Connection window to simplify demonstrations based on your own environment setup.

Announcing the SQLskills Availability Group Demonstrator   image thumb

The settings in the configuration file provide the default values for the following options in the New Connection window.

Announcing the SQLskills Availability Group Demonstrator   image thumb

Using the application

I usually start out with a simple Availability Group (hereafter referred to as an AG) configuration where a SQL Server login is used and the AG was created through the UI.  I use the application to connect directly to the primary server using a SQL Server login without using the Availability Group Listener to show how you can connect directly to the primary server with its name.  Then I perform a failover to the synchronous replica that is configured for high availability, and open a new connection to show that the connectivity will fail since the SQL Server login wasn’t created on the secondary.  Then I use DDL to create the login and show that even though I’ve created the login on the secondary, it will fail because the SID for the new login isn’t the same as the SID that existed on the original primary server.  At this point I explain that you could use sp_help_revlogin to transfer the login with the SID intact, but then show that Partially Contained Databases with database authentication can prevent having to manually migrate every login, so I failover to the original primary and setup partial containment on all the nodes and migrate the server level login to being a contained database login.  Then I close all of the connection windows and create a new connection that uses the Availability Group Listener for the connection so that I can then failover between the primary replica and the high availability synchronous successfully. A single New Connection in the application can support this.

Then I configure ReadOnly routing for the AG and show two connections, one configured for the Read/Write workload, and another configured as a ReadOnly connection to the listener using a ReadOnly workload.

Announcing the SQLskills Availability Group Demonstrator   image thumb

After setting up ReadOnly routing, and then specifying that the connection is for ReadOnly operation in the application, it will automatically redirect the connections to the first readable secondary in the routing configuration as expected.  Performing a failover will allow the application to show the expected failover error messages and then redirect the applications connections based on the configuration of the ApplicationConnection windows to the desired hosts in the AG.

Announcing the SQLskills Availability Group Demonstrator   image thumb

An example of the failover messages returned is below:

Announcing the SQLskills Availability Group Demonstrator   image thumb  

Once the failover completes, the application will reconnect to the appropriate nodes based on the ReadOnly routing configuration for the AG.

Requirements

The application requires .NET 4.0 and the SQL Server 2012 Native Client be installed to make use of the new ApplicationIntent connection string option. 

UPDATE:

You also need to create the following table in whatever database you are using for the demonstration:

USE [DBNAME]
GO
CREATE TABLE InsertCount (RowID int identity primary key)
GO
INSERT INTO InsertCount DEFAULT VALUES;
GO

The application can be downloaded from:

http://www.sqlskills.com/free-tools/availability-group-demonstrator/ 

If you have any questions, feel free to email me at jonathan@sqlskills.com or through the contact form on this blog.

Looking at Non-Updating Updates with Extended Events

For a few weeks now, there has been a long running thread on SQL Server Central about UPDATE operations that don't perform any changes because the statement sets a column to the same value as already exists in the row.  While I believe that one of the posters is incredibly snarky and outright rude to the people trying to answer the question and explain the behaviors being noticed, the topic is quite interesting and I finally got some time on my flight to Seattle to take a look at some of the internals of this with Extended Events in SQL Server 2012. 

Setting up the Tests

To setup the tests to be performed I am going to use the example table and row of data that are provided in that thread for the investigation with the exception that I am going to use a user database instead of tempdb for holding the test table so that I can create separate tests for a case-sensitive collation versus case-insensitive collations.

– Create the case-insensitive database
CREATE DATABASE TestUpdate COLLATE SQL_Latin1_General_CP1_CI_AI
GO
USE TestUpdate;
GO
CREATE TABLE Test
(
    ID         INT IDENTITY(1,1) NOT NULL,
    Name    VARCHAR(100) COLLATE SQL_Latin1_General_CP1_CI_AI NOT NULL
);
GO
INSERT dbo.Test
    (Name)
VALUES
    ('Tom');
GO
CHECKPOINT;
GO

– Create the case-sensitive database
CREATE DATABASE [TestUpdateCS] COLLATE SQL_Latin1_General_CP1_CS_AS
GO
USE TestUpdateCS;
GO
CREATE TABLE Test
(
    ID      INT IDENTITY(1,1) NOT NULL,
    Name    VARCHAR(100) COLLATE SQL_Latin1_General_CP1_CS_AS NOT NULL
);
GO
INSERT dbo.Test
    (Name)
VALUES
    ('Tom');
GO
CHECKPOINT;
GO

Then to setup the Extended Events session for collecting information about the operations being performed, we are going to collect a number of events in the engine along with the callstack for each even and the filter on the session_id where the tests are actually being run to prevent collecting data that is not related to the tests being executed.  I originally started with nearly double the events, but removed the events that were not firing for any of the tests from the final event session shown below.

IF EXISTS (SELECT 1 FROM sys.server_event_sessions
            WHERE name = 'SQLskills_InvestigatingUpdates')
BEGIN
    DROP EVENT SESSION [SQLskills_InvestigatingUpdates] ON SERVER;
END
GO
CREATE EVENT SESSION [SQLskills_InvestigatingUpdates]
ON SERVER
– Track sparse file writes for snapshots
ADD EVENT sqlserver.file_written_to_replica(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
– Track memory page allocations
ADD EVENT sqlos.page_allocated(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlos.page_freed(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
– Track latching
ADD EVENT sqlserver.latch_acquire_time(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.latch_suspend_begin(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.latch_suspend_end(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
– Track locking
ADD EVENT sqlserver.lock_acquired(
    SET collect_database_name = 1
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.lock_released(
    SET collect_database_name = 1
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
– Track transaction log activity
ADD EVENT sqlserver.log_flush_requested(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.log_single_record(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.transaction_log(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
– Track batch and statement activity
ADD EVENT sqlserver.sql_batch_completed(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.sql_batch_starting(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.sql_statement_completed(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62))),
ADD EVENT sqlserver.sql_statement_starting(
    ACTION(package0.callstack,sqlserver.session_id)
    WHERE ([sqlserver].[session_id]=(62)))
– Store event data in ring_buffer target
ADD TARGET package0.ring_buffer;
GO

Testing Methodolgy

From the original thread on SQL Server Central, there are a couple of sticking points that keep getting brought up so in the interests of attempting to be thorough I am going to provide the testing methodology being used, and then list all of the tests that are going to be run. 

  1. All tests will be conducted against both of the databases to identify behavior changes between CS and CI collations if they occur. 
  2. At the start of every test, the data in the tables will have 'Tom' for the Name column.  If a previous test has changed the value to something different it will be reset before the test is executed.
  3. The event session will be stopped and started between each test to isolate the data collect to each individual test.
  4. At least one minute of time will be waited for between tests to allow the background thread that performs row version cleanup to execute and remove row versions that may have been created by the tests. (http://msdn.microsoft.com/en-us/library/ms175492(v=sql.105).aspx)
  5. All of the tests will be run once initially to allow the execution plan to be generated and cached in the plan cache, and then the test will be reset and rerun so that the event session doesn't capture the page allocations and locking/latching associated with compiling/caching the plans.

Tests

The tests that will be performed are as follows:

  1. Determine the way that SQL Server handles UPDATE statements that set the column to the same value that previously existed without filtering.

    – Non-updating update
    UPDATE dbo.Test
    SET Name = Name;
    GO

    – Non-updating update
    UPDATE dbo.Test
    SET Name = 'Tom';
    GO

  2. Determine the way that SQL Server handles UPDATE statements that change the value that previously existed without filtering.

    – Updating update
    UPDATE dbo.Test
    SET Name = 'TOM';
    GO

  3. Determine the way that SQL Server handles UPDATE statements that set the column to the same value that previously existed with filtering.

    – Non-Updating with filter
    UPDATE dbo.Test
    SET Name = Name
    WHERE Name != 'Tom';
    GO

    – Non-Updating with filter
    UPDATE dbo.Test
    SET Name = 'Tom'
    WHERE Name != 'Tom';
    GO

  4. Determine the way that SQL Server handles UPDATE statements that change the value that previously existed with filtering.

    – Updating update
    UPDATE dbo.Test
    SET Name = 'TOM'
    WHERE Name != 'TOM';
    GO

All of these tests will be run against the CS and CI database.  Additionally after the first tests are performed against a table without a trigger, the tests will be repeated with the following FOR/AFTER UPDATE trigger on the tables.

CREATE TRIGGER trg_AuditChanges_Test
ON Test
FOR UPDATE
AS
BEGIN
DECLARE @ins INT;
DECLARE @del INT;

SELECT @ins = COUNT(*)
FROM inserted;

SELECT @del = COUNT(*)
FROM deleted;

END
GO

I am not going to include the 16 frame callstack in the results in this post except where it provides useful information for the investigation of the results being collected.  The callstack results in this post will be materialized through the use of Trace Flag 3656 and the public symbols as I explained in my blog post about the callstack action in the XEvent a Day series, An XEvent a Day (24 of 31) – What is the callstack?.

Results No Trigger

For both of the UPDATE statements in test number 1, the following events ( they are identical for both scenarios ) are generated by the event session.  Note that the locks acquired include a conversion of the U lock on the RID to an X lock as a part of the execution,  and even though the UPDATE doesn't actually make any changes, two log records are generated for the BEGIN_XACT and COMMIT_XACT, and these have to also be flushed to the transaction log file, as shown by the log_flush_requested event.

event_name lock_resource_type lock_mode status log_op_name context database_id resource_0
sql_batch_starting NULL NULL NULL NULL NULL NULL NULL
sql_statement_starting NULL NULL NULL NULL NULL NULL NULL
lock_acquired OBJECT IX NULL NULL NULL 9 245575913
latch_acquire_time NULL NULL HASHED, ONLRU NULL NULL NULL NULL
lock_acquired PAGE IU NULL NULL NULL 9 228
lock_acquired RID U NULL NULL NULL 9 228
lock_acquired PAGE IX NULL NULL NULL 9 228
lock_acquired RID X NULL NULL NULL 9 228
log_single_record NULL NULL NULL LOP_BEGIN_XACT NULL 9 NULL
transaction_log NULL NULL NULL LOP_BEGIN_XACT NULL 9 NULL
lock_released RID NL NULL NULL NULL 9 228
lock_released PAGE NL NULL NULL NULL 9 228
log_single_record NULL NULL NULL LOP_COMMIT_XACT NULL 9 NULL
transaction_log NULL NULL NULL LOP_COMMIT_XACT NULL 9 NULL
log_flush_requested NULL NULL NULL NULL NULL 9 NULL
lock_released RID X NULL NULL NULL 9 228
lock_released PAGE IX NULL NULL NULL 9 228
lock_released OBJECT IX NULL NULL NULL 9 245575913
sql_statement_completed NULL NULL NULL NULL NULL NULL NULL
sql_batch_completed NULL NULL NULL NULL NULL NULL NULL

If we compare this to the UPDATE statement that actually performs a change to the data in the row from test number 2, we will see that additional log records are generated for the MODIFY_ROW operation, and then flushed to the log file.

event_name lock_resource_type lock_mode status log_op_name context database_id resource_0
sql_batch_starting NULL NULL NULL NULL NULL NULL NULL
sql_statement_starting NULL NULL NULL NULL NULL NULL NULL
lock_acquired OBJECT IX NULL NULL NULL 9 245575913
lock_acquired PAGE IU NULL NULL NULL 9 228
lock_acquired RID U NULL NULL NULL 9 228
lock_acquired PAGE IX NULL NULL NULL 9 228
lock_acquired RID X NULL NULL NULL 9 228
log_single_record NULL NULL NULL LOP_BEGIN_XACT NULL 9 NULL
transaction_log NULL NULL NULL LOP_BEGIN_XACT NULL 9 NULL
log_single_record NULL NULL NULL LOP_MODIFY_ROW NULL 9 NULL
transaction_log NULL NULL NULL LOP_MODIFY_ROW HEAP 9 NULL
lock_released RID NL NULL NULL NULL 9 228
lock_released PAGE NL NULL NULL NULL 9 228
log_single_record NULL NULL NULL LOP_COMMIT_XACT NULL 9 NULL
transaction_log NULL NULL NULL LOP_COMMIT_XACT NULL 9 NULL
log_flush_requested NULL NULL NULL NULL NULL 9 NULL
lock_released RID X NULL NULL NULL 9 228
lock_released PAGE IX NULL NULL NULL 9 228
lock_released OBJECT IX NULL NULL NULL 9 245575913
sql_statement_completed NULL NULL NULL NULL NULL NULL NULL
sql_batch_completed NULL NULL NULL NULL NULL NULL NULL

For the UPDATE statement in test number 3 where a WHERE clause is applied to check the column value against the value being set to ensure that they are not the same values, the results are different as shown below:

event_name lock_resource_type lock_mode status log_op_name context database_id resource_0
sql_batch_starting NULL NULL NULL NULL NULL NULL NULL
sql_statement_starting NULL NULL NULL NULL NULL NULL NULL
lock_acquired OBJECT IX NULL NULL NULL 9 245575913
lock_acquired PAGE IU NULL NULL NULL 9 228
lock_acquired RID U NULL NULL NULL 9 228
lock_released RID U NULL NULL NULL 9 228
lock_released PAGE IU NULL NULL NULL 9 228
lock_released OBJECT IX NULL NULL NULL 9 245575913
sql_statement_completed NULL NULL NULL NULL NULL NULL NULL
sql_batch_completed NULL NULL NULL NULL NULL NULL NULL

Notice that here we don't have the lock conversion for the RID from U to X, and we don't have the log records being generated and flushed to the transaction log for the BEGIN_XACT and COMMIT_XACT. 

The results for the UPDATE in test number 4 has the same outcome as shown above for test number 3 when run against the case-insensitive collation database.  However, running test number 4 against the case-sensitive collation database results in the same events being fired for the non-filtered UPDATE and data changes in the table with the LOP_MODIFY_ROWS log records being generated. (Feel free to test and validate this using the provided code and CS collation database)

Results FOR/AFTER UPDATE Triggers

The results for the two UPDATE statements in test number 1 when a trigger exists on the table are different than when the table does not have the trigger on it.

event_name lock_resource_type lock_mode status log_op_name context database_id resource_0
sql_batch_starting NULL NULL NULL NULL NULL NULL NULL
sql_statement_starting NULL NULL NULL NULL NULL NULL NULL
lock_acquired OBJECT IX NULL NULL NULL 10 245575913
lock_acquired PAGE IU NULL NULL NULL 10 357
lock_acquired RID U NULL NULL NULL 10 357
lock_acquired PAGE IX NULL NULL NULL 10 357
lock_acquired RID X NULL NULL NULL 10 357
page_allocated NULL NULL NULL NULL NULL NULL NULL
log_single_record NULL NULL NULL LOP_BEGIN_XACT NULL 10 NULL
transaction_log NULL NULL NULL LOP_BEGIN_XACT NULL 10 NULL
lock_acquired EXTENT X NULL NULL NULL 2 1568
lock_released EXTENT X NULL NULL NULL 2 1568
page_allocated NULL NULL NULL NULL NULL NULL NULL
page_allocated NULL NULL NULL NULL NULL NULL NULL
page_allocated NULL NULL NULL NULL NULL NULL NULL
page_allocated NULL NULL NULL NULL NULL NULL NULL
page_allocated NULL NULL NULL NULL NULL NULL NULL
page_allocated NULL NULL NULL NULL NULL NULL NULL
page_allocated NULL NULL NULL NULL NULL NULL NULL
page_allocated NULL NULL NULL NULL NULL NULL NULL
latch_acquire_time NULL NULL CHKGEN, DIRTY, HASHED, ON NULL NULL NULL NULL
lock_acquired EXTENT U NULL NULL NULL 2 312
lock_acquired PAGE X NULL NULL NULL 2 318
lock_released EXTENT U NULL NULL NULL 2 312
lock_released PAGE X NULL NULL NULL 2 318
lock_released RID NL NULL NULL NULL 10 357
lock_released PAGE NL NULL NULL NULL 10 357
latch_acquire_time NULL NULL CHKGEN, DIRTY, HASHED, ON NULL NULL NULL NULL
log_single_record NULL NULL NULL LOP_COMMIT_XACT NULL 10 NULL
transaction_log NULL NULL NULL LOP_COMMIT_XACT NULL 10 NULL
log_flush_requested NULL NULL NULL NULL NULL 10 NULL
lock_released RID X NULL NULL NULL 10 357
lock_released PAGE IX NULL NULL NULL 10 357
lock_released OBJECT IX NULL NULL NULL 10 245575913
sql_statement_completed NULL NULL NULL NULL NULL NULL NULL
sql_batch_completed NULL NULL NULL NULL NULL NULL NULL

As you can see in the table above, we now have exclusive locks on an extent in tempdb, and memory page allocations occurring (shown by the page_allocated events) in the new result set.  If we take a look at the execution callstack for the page_allocated events, we'll see:

MemoryClerkInternal::AllocatePages+26f [ @ 0+0×0
BPool::Steal+35a [ @ 0+0×0
BPool::NewPage+7af [ @ 0+0×0
PageRef::FormatInternal+8e [ @ 0+0×0
AppendOnlyStorageUnit::SetupPageHeaderPreAllocation+af [ @ 0+0×0
AllocationReq::AllocateExtent+285 [ @ 0+0×0
AllocationReq::AllocateFirst+a9a [ @ 0+0×0
AllocationReq::Allocate+e9 [ @ 0+0×0
AppendOnlyStorageUnit::AllocateNewExtent+29a [ @ 0+0×0
AppendOnlyVerStoreMgr::AddRecord+e07 [ @ 0+0×0
VersionMgr::InsertNewImage+13e [ @ 0+0×0
HeapPageRef::Update+b4e [ @ 0+0×0
HeapFragment::Update+3b7 [ @ 0+0×0
HeapRowObject::Update+67d9 [ @ 0+0×0
HeapDataSetSession::SetDataInternal+8dcb [ @ 0+0×0
DatasetSession::SetData+16d [ @ 0+0×0
RowsetNewSS::SetData+6a [ @ 0+0×0
CValRow::SetDataX+63 [ @ 0+0×0
CEsExec::GeneralEval4+e7 [ @ 0+0×0
CQScanUpdateNew::GetRow+23a [ @ 0+0×0
CQueryScan::GetRow+81 [ @ 0+0×0
CXStmtQuery::ErsqExecuteQuery+36a [ @ 0+0×0
CXStmtDML::XretDMLExecute+2b9 [ @ 0+0×0
CXStmtDML::XretExecute+ad [ @ 0+0×0

By adding the trigger, we now have version store records being generated associated with the execution of the FOR/AFTER UPDATE trigger.  The version store records are also generated for test number 2 where the column data is actually changed by the UPDATE statement being executed.  On the case-insensitive collation, test number 3 and number 4 do not generate version store records.

However, for the case-sensitive collation, test number 4 does generate version store records, as shown below:

event_name lock_resource_type lock_mode status log_op_name context database_id resource_0
sql_batch_starting NULL NULL NULL NULL NULL NULL NULL
sql_statement_starting NULL NULL NULL NULL NULL NULL NULL
lock_acquired OBJECT IX NULL NULL NULL 10 325576198
latch_acquire_time NULL NULL HASHED, ONLRU NULL NULL NULL NULL
latch_acquire_time NULL NULL DIRTY, HASHED, ONLRU NULL NULL NULL NULL
lock_acquired PAGE IU NULL NULL NULL 10 73
lock_acquired RID U NULL NULL NULL 10 73
lock_acquired PAGE IX NULL NULL NULL 10 73
lock_acquired RID X NULL NULL NULL 10 73
log_single_record NULL NULL NULL LOP_BEGIN_XACT NULL 10 NULL
transaction_log NULL NULL NULL LOP_BEGIN_XACT NULL 10 NULL
latch_acquire_time NULL NULL HASHED, ONLRU NULL NULL NULL NULL
lock_acquired EXTENT X NULL NULL NULL 2 2944
lock_released EXTENT X NULL NULL NULL 2 2944
lock_acquired EXTENT U NULL NULL NULL 2 264
lock_acquired PAGE X NULL NULL NULL 2 269
lock_released EXTENT U NULL NULL NULL 2 264
lock_released PAGE X NULL NULL NULL 2 269
log_single_record NULL NULL NULL LOP_MODIFY_ROW NULL 10 NULL
transaction_log NULL NULL NULL LOP_MODIFY_ROW HEAP 10 NULL
lock_released RID NL NULL NULL NULL 10 73
lock_released PAGE NL NULL NULL NULL 10 73
log_single_record NULL NULL NULL LOP_COMMIT_XACT NULL 10 NULL
transaction_log NULL NULL NULL LOP_COMMIT_XACT NULL 10 NULL
log_flush_requested NULL NULL NULL NULL NULL 10 NULL
lock_released RID X NULL NULL NULL 10 73
lock_released PAGE IX NULL NULL NULL 10 73
lock_released OBJECT IX NULL NULL NULL 10 325576198
sql_statement_completed NULL NULL NULL NULL NULL NULL NULL
sql_batch_completed NULL NULL NULL NULL NULL NULL NULL

The page_allocated events have the same callstack as the previously listed callstack in this post.

Conclusions

As can be seen by the results of these tests, UPDATE statements that do not actually change the value of a column in a row, can still have overhead associated with them, even when the database engine is recognizes that no change is actually occurring and doesn't actually affect the row on the page.  There is still overhead for the exclusive lock conversion and the implicit transaction that occurs as a part of the UPDATE occurring when no filter is provided to check the value currently on the row against the value being SET, and there is added overhead for row versioning if triggers exist on the table.

Looking at the callstack for the LOP_MODIFY_ROW log operation, we can also see that changes being made affect the specific row on the page.  The changes are NOT made on a separate page allocated by SQL Server to allow a binary comparison of the two pages, as suggested in the original forum thread that lead to this investigation. This is NOT how SQL Server behaves.

SQLServerLogMgr::FireAppendXevent+11b [ @ 0+0×0
SQLServerLogMgr::AppendLogRequest+6d8 [ @ 0+0×0
SQLServerLogMgr::ReserveAndAppend+74 [ @ 0+0×0
XdesRMReadWrite::GenerateLogRec+5ac [ @ 0+0×0

PageRef::ModifyRow+2b4a [ @ 0+0×0


PageRef::ModifyColumnsInternal+162 [ @ 0+0×0

HeapPageRef::Update+208d [ @ 0+0×0
HeapFragment::Update+3b7 [ @ 0+0×0
HeapRowObject::Update+67d9 [ @ 0+0×0
HeapDataSetSession::SetDataInternal+8dcb [ @ 0+0×0
DatasetSession::SetData+16d [ @ 0+0×0
RowsetNewSS::SetData+6a [ @ 0+0×0
CValRow::SetDataX+63 [ @ 0+0×0
CEsExec::GeneralEval4+e7 [ @ 0+0×0

CQScanUpdateNew::GetRow+23a [ @ 0+0×0
CQueryScan::GetRow+81 [ @ 0+0×0

CXStmtQuery::ErsqExecuteQuery+36a [ @ 0+0×0
CXStmtDML::XretDMLExecute+2b9 [ @ 0+0×0
CXStmtDML::XretExecute+ad [ @ 0+0×0
CMsqlExecContext::ExecuteStmts<0,0>+1a71 [ @ 0+0×0
CMsqlExecContext::FExecute+a4f [ @ 0+0×0
CSQLSource::Execute+866 [ @ 0+0×0
CStmtPrepQuery::XretPrepQueryExecute+3e2 [ @ 0+0×0
CMsqlExecContext::ExecuteStmts<1,0>+17c6 [ @ 0+0×0

This is further supported by the fact that no additional page_allocated events fire outside of the version store information being generated by the UPDATE.  Since these tests only focused on the internal operations of UPDATE statements against a single row table, no realistic determination can be made for the actual performance overhead of comparing the column value to the value being SET by the UPDATE statement, specifically for what additional overhead might be incurred by a less ideal execution plan based on the additional filter criteria being optimized.  This is something that I will definitely be looking at in more detail for a possible later post.  However, we can see that comparing the current value to the value being set, can affect row version generation, lock conversions, and the number of log records that are generated where the data would not actually be changed by the UPDATE statement being issued.

Addition:

For further reading on this subject, take a look at Paul Whites blog post from a few years ago.  The outcomes are the same, but he uses a different method of investigation 

The Availability Group Wizard and the HADR Seeding Test Database

If you are creating an Availability Group in SQL Server 2012 using the New Availability Group Wizard in SQL Server Management Studio, you might not realize some of the background tasks that the wizard performs when it performs its validation steps.  One of those steps is to create a temporary database on the current server that has a name in the format of [HADR Seeding Test <UniqueIdentifier>], which is then backed up to the network share location specified, and then each of the secondary replica’s attempts a restore of the backup from the network share to validate that the appropriate permissions exist for the service accounts to the share.  This can all be seen in the Default Trace information on each of the servers.

The Default Trace from the server that the wizard is being run against as the Primary will show:

The Availability Group Wizard and the HADR Seeding Test Database   image thumb

The secondary replicas being configured will show:

The Availability Group Wizard and the HADR Seeding Test Database   image thumb

This is strictly an artifact of how the wizard validates the configuration being provided to ensure that it will be able to successfully create the Availability Group.  If you create the Availability Group from scripts or through PowerShell and manually perform the backup/restore operations this database will not be created.

Enlarging the AdventureWorks Sample Databases

The AdventureWorks set of sample databases are commonly used for presentation demos and showing how to use SQL Server, but one of the biggest challenges in using these databases is their small size which is geared towards ease of distribution, more than demonstrating all of the functionality of SQL Server.  The concept of creating a larger version of AdventureWorks is not new, Adam Machanic (Blog|Twitter) blogged last year about enlarging specific tables for demonstrations, and at the same time I found that I also needed to create tables that were larger datasets for my own purposes.  The tables that I chose to enlarge for demonstration purposes were the Sales.SalesOrderHeader and Sales.SalesOrderDetail tables which can be used to demonstrate a number of different query plan and performance issues in SQL Server.  Below is a script that can enlarge these tables into tables named Sales.SalesOrderHeaderEnlarged and Sales.SalesOrderDetailEnlarged in the specific AdventureWorks database being targeted.  The attached script has been tested against the AdventureWorks2008R2 and AdventureWorks2012 databases specifically, but as long as the table schema is the same it may be applied to any version of AdventureWorks.

These larger tables can be used to produce parallel execution plans, plans that have large execution memory grant requirements, plans that perform sort and hash spill operations through tempdb, and many other uses in SQL Server.  The size of the tables can be scaled by running the INSERT code block multiple times to increase the size of the Sales.SalesOrderHeader table by roughly 225MB, and to increase the size of the Sales.SalesOrderDetailEnlarged table by roughly 400MB per execution after the index rebuilds are run.

Create Enlarged AdventureWorks Tables.sql (8.43 kb)

Tracking Extended Events for a SQL Agent Job

This blog post is courtesy of a question I received from Chris Adkin (Twitter) by email.  Chris was trying to use Extended Events to track session level wait information, but he had a new twist that I’ve never been asked about before, he wanted to track all of the waits for a specific SQL Agent job anytime it executed.  I knew immediately when I read the email that this was definitely possible, but it required some additional information about SQL Agent. 

Initially it might seem like this would be a good scenario to filter on sqlserver.session_id, but that won’t work because the session_id is not guaranteed to be the same across executions.  I thought about using one job step to ALTER the event session, but that won’t be guaranteed to catch everything for the next step in the job.  Then I thought back to a few years ago and I wanted to track long running Agent jobs on my servers, and then I remembered that you can do this with the program_name or in Extended Events, the sqlserver.client_app_name global predicate field.  To demonstrate this, I created a job on my VM that calls a simple WAITFOR DELAY in the first job step and then I ran the job and queried sys.dm_exec_sessions to get the program name.

SQLAgent – TSQL JobStep (Job 0x6F4E4936767BEA4CBE088245356A5C54 : Step 1)

If we take this and compare it to the job_id in msdb.dbo.sysjobs for the job, we can see that the guid for the job_id has been transposed to create the program_name being used:

36494E6F-7B76-4CEA-BE08-8245356A5C54

So with this information, we now define a predicate that will allow our Event Session to collect events specifically for our job execution as follows:

DECLARE @JobName NVARCHAR(128) = 'Test';

DECLARE @Predicate NVARCHAR(MAX)='';
DECLARE @sqlcmd NVARCHAR(MAX)='';

SET @sqlcmd ='IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name=''TrackResourceWaits'')
    DROP EVENT SESSION [TrackResourceWaits] ON SERVER;
CREATE EVENT SESSION [TrackResourceWaits] ON SERVER 
ADD EVENT  sqlos.wait_info
(   WHERE
        (opcode = 1 --End Events Only
            AND duration > 0 -- had to accumulate 100ms of time
            AND ({0})
        ))
ADD TARGET package0.asynchronous_bucketizer
(     SET filtering_event_name=''sqlos.wait_info'',
        source_type=0, -- specifies bucketing on column 
        source=''wait_type'' -- Bucket by wait_type
),
ADD TARGET package0.ring_buffer(SET max_memory=4096)';

SELECT @Predicate = @Predicate + 
    'sqlserver.client_app_name = ''' +
    'SQLAgent - TSQL JobStep (Job 0x'+
    SUBSTRING(job_id,7,2) +
    SUBSTRING(job_id,5,2) +
    SUBSTRING(job_id,3,2) +
    SUBSTRING(job_id,1,2) +
    SUBSTRING(job_id,12,2) +
    SUBSTRING(job_id,10,2) +
    SUBSTRING(job_id,17,2) +
    SUBSTRING(job_id,15,2) +
    SUBSTRING(job_id,20,4) +
    SUBSTRING(job_id,25,12) + 
    ' : Step ' + 
    CAST(step_id AS VARCHAR(3)) + 
    ')'' OR '
FROM( SELECT CAST(j.job_id AS VARCHAR(50)) AS job_id,
            js.step_id
        FROM msdb.dbo.sysjobs AS j
        INNER JOIN msdb.dbo.sysjobsteps AS js
            ON j.job_id = js.job_id
        WHERE j.name = @JobName) AS tab;

-- Append the predicate into the SQL command
SET @sqlcmd = REPLACE(@sqlcmd, '{0}', LEFT(@Predicate, LEN(@Predicate)-3));

-- Create the Event Session
EXEC(@sqlcmd);

Now as I pointed out in my original post about collecting session level wait stats, this doesn’t necessarily provide actionable data since it doesn’t tell us about the other activity on the server that may be causing specific waits to occur.  For example, if you run this and see that there are high I/O waits, but concurrently at the same time there is a DBCC CHECKDB running on the server that is saturating the I/O subsystem, all we know about for the data collected is that there were high I/O waits, it doesn’t tell us why they might exist.  For some wait types this might be very actionable, but I would use caution tracking session or task specific waits because the same waits will not occur on different hardware, or under different conditions on the same exact hardware. 

Identifying High Compile Time Statements from the Plan Cache

If you don’t already know it, I love query the plan cache in SQL Server to identify problems that might exist in a server.  I’ve blogged a number of ways to use plan cache data to identify and diagnose problems the last few years:

Finding what queries in the plan cache use a specific index
Tuning ‘cost threshold for parallelism’ from the Plan Cache
Finding Implicit Column Conversions in the Plan Cache
Digging into the SQL Plan Cache: Finding Missing Indexes

Last week on the forums a question was asked about how to use Extended Events to identify queries that took excessive amounts of time to compile.  What intrigued me was that the person asking the question claimed to have done this type of analysis with SQL Trace, so in 2012, that should mean that we can do it with Extended Events, right?  As Borat would say, not so much!

After seeing the events being used I took a look at the Event map, and while there is a loose mapping between the trace events that were being used to Extended Events, not all the same data is generated.  The primary event in trace that was being used for this is the Performance Statistics event, which is has a trace event id of 165.  If we lookup this event in the sys.trace_xe_event_map table in SQL Server 2012, we’ll find that it maps to three different events in Extended Events; query_cache_removal_statistics, query_pre_execution_showplan, and uncached_sql_batch_statistics. 

Immediately, I said to myself, “No, this isn’t possible in Extended Events.” simply because the overhead of turning on query_pre_execution_showplan, will kill performance of any production server (see http://connect.microsoft.com/SQLServer/feedback/details/732870/sqlserver-query-post-execution-showplan-performance-impact which is for the query_post_execution_showplan event, but all of the showplan events have the same impact).  Looking at the columns for the other two events, left me basically in the same mindset, you can’t do this with Extended Events.  The uncached_sql_batch_statistics event only captures the statement that wasn’t cached, and the query_cache_removal_statistics only gives you the execution statistics, not the parse and compile times.  Even if you were to turn on the query_pre_execution_showplan event, it doesn’t provide you with the CPU and duration columns for output, so it is not going to be useful here.

To be honest, I didn’t think that this was going to be possible, but then I thought about some of the fun we had in our Immersion Event week two in London looking at query compile issues, and I remembered that I wrote a parser between modules to pull compile time information from the showplans in the plan cache.  After searching through some scratch code files in my user profile I found a relevant one and started playing around a little with the XML parsing.  The result is the below query, which identifies the TOP 10 most expensive to compile statements in the cache currently, and includes the query stats for the statement, based on the query_hash, though it could be easily modified to use query_plan_hash to match on instead.

-- Find high compile resource plans in the plan cache
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
WITH XMLNAMESPACES 
(DEFAULT 'http://schemas.microsoft.com/sqlserver/2004/07/showplan')
SELECT TOP 10
CompileTime_ms,
CompileCPU_ms,
CompileMemory_KB,
qs.execution_count,
qs.total_elapsed_time/1000 AS duration_ms,
qs.total_worker_time/1000 as cputime_ms,
(qs.total_elapsed_time/qs.execution_count)/1000 AS avg_duration_ms,
(qs.total_worker_time/qs.execution_count)/1000 AS avg_cputime_ms,
qs.max_elapsed_time/1000 AS max_duration_ms,
qs.max_worker_time/1000 AS max_cputime_ms,
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 StmtText,
query_hash,
query_plan_hash
FROM
(
SELECT 
c.value('xs:hexBinary(substring((@QueryHash)[1],3))', 'varbinary(max)') AS QueryHash,
c.value('xs:hexBinary(substring((@QueryPlanHash)[1],3))', 'varbinary(max)') AS QueryPlanHash,
c.value('(QueryPlan/@CompileTime)[1]', 'int') AS CompileTime_ms,
c.value('(QueryPlan/@CompileCPU)[1]', 'int') AS CompileCPU_ms,
c.value('(QueryPlan/@CompileMemory)[1]', 'int') AS CompileMemory_KB,
qp.query_plan
FROM sys.dm_exec_cached_plans AS cp
CROSS APPLY sys.dm_exec_query_plan(cp.plan_handle) AS qp
CROSS APPLY qp.query_plan.nodes('ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple') AS n(c)
) AS tab
JOIN sys.dm_exec_query_stats AS qs
ON tab.QueryHash = qs.query_hash
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) AS st
ORDER BY CompileTime_ms DESC
OPTION(RECOMPILE, MAXDOP 1);

Running this against a couple of test servers, I found a couple of queries that had 12 second compile times with 3 second execution durations.  Now the challenge becomes testing if the query can be simplified to reduce the time it takes the optimizer to compile it, without reducing execution performance.  The above code should work on any version of SQL Server from 2005 Service Pack 2 onwards, since the CompileTime, Compile CPU, and CompileMemory attributes were added in Service Pack 2.  I don’t have a SQL Server 2005 instance to test it on, but I did test this on SQL Server 2008 and 2012.

EDIT:

This only works on 2008 and higher because the query fingerprints in dm_exec_query_stats weren't in SQL Server 2005.  Using plan_handle will get you close, but that only tells you the plan had a high compile cost statement in it.  You will have to dig into the plan to see which specific statement, which I am trying to avoid with the code above.  I'll have to figure out another way to match these up based on the XML and blog the 2005 solution.