And YOU Get a Deadlock and YOU Get a Deadlock and EVERYBODY GETS A DEADLOCK!

https://memegenerator.net/img/instances/400x/59507872/you-get-a-deadlock-everybody-gets-a-deadlock.jpg

We all get them at one point or another - deadlocks.

I have Object 1 and need Object 2, you have Object 2 and need Object 1:

https://i-technet.sec.s-msft.com/dynimg/IC4289.gif

This isn't the same as simple blocking, where I have Object 1 and you want it (but you can't have it because it's MINE!)  In that case you just need to wait your turn, and eventually you will get sick of waiting and walk away (timeout) or I will get done with it and surrender it to you.

In the deadlock case, there truly is no way out other than terminating one of the two requests - in the example above transaction 1 needs access to the Part table to proceed with its work on the Supplier table, and transaction 2 needs access to the Supplier table to work with the Part table.  This means everyone is stuck.

A great (yet sad) non-techie way of describing a deadlock is this:

https://cdn.meme.am/instances/27106434/no-job-because-no-experience-no-experience-because-no-job.jpg

--

SQL Server has a process called the Deadlock Monitor that periodically watches for deadlock situations and handles them by terminating one or more processes to clear the logjam.  As described in Technet:

By default, the Database Engine chooses as the deadlock victim the session running the transaction that is least expensive to roll back. Alternatively, a user can specify the priority of sessions in a deadlock situation using the SET DEADLOCK_PRIORITY statement. DEADLOCK_PRIORITY can be set to LOW, NORMAL, or HIGH, or alternatively can be set to any integer value in the range (-10 to 10). The deadlock priority defaults to NORMAL. If two sessions have different deadlock priorities, the session with the lower priority is chosen as the deadlock victim. If both sessions have the same deadlock priority, the session with the transaction that is least expensive to roll back is chosen. If sessions involved in the deadlock cycle have the same deadlock priority and the same cost, a victim is chosen randomly.

"Least Expensive to Roll Back" can sometimes be difficult to determine although a general guideline is that SELECT statements are the least expensive (with no LOG to roll back) and are frequent deadlock victims.

--

With all of that in hand, how do you gather information about deadlocks?  Classical deadlock troubleshooting relies on trace flags 1204 and 1222 or a SQL Server trace on the Deadlock Chain and Deadlock Graph events (as described in this MSSQLTip).

https://www.toonpool.com/user/589/files/living_in_the_past_333905.jpg

We all know at this point (whether some people want to admit it or not) that Extended Events are the tool of the future for this kind of work.  They are more lightweight than SQL Server Trace and are continuing to be improved (unlike Trace, which has been stagnant since SQL Server 2005!)  Any time you find yourself using Trace or Profiler you should pause and reflect on how to accomplish the same task with XEvents.

In this case, there is deadlock information in the System_Health Session, the basic session deployed by default on all SQL Server instances since SQL Server 2008.  (Think the better, stronger, faster version of the Default Trace.)  Patrick Keisler (blog/@PatrickKeisler) has a great write-up about the System_Health session on his blog here.

By default deadlock information is one giant character field that is formatted for XML.  The XML is readable (sort of) if that's your thing:

--

<deadlock>

  <victim-list>

    <victimProcess id="process5776a5498" />

  </victim-list>

  <process-list>

    <process id="process5776a5498" taskpriority="0" logused="0" waitresource="KEY: 19:72057594040745984 (9ba325989765)" waittime="4168" ownerId="327954909" transactionname="SELECT" lasttranstarted="2017-10-17T17:21:04.417" XDES="0x50560f9d0" lockMode="S" schedulerid="1" kpid="3756" status="suspended" spid="64" sbid="0" ecid="0" priority="0" trancount="0" lastbatchstarted="2017-10-17T17:21:04.417" lastbatchcompleted="2017-10-17T17:21:03.293" lastattention="1900-01-01T00:00:00.293" hostpid="4012" loginname="Login1" isolationlevel="read committed (2)" xactid="327954909" currentdb="19" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">

      <executionStack>

        <frame procname="adhoc" line="1" sqlhandle="0x0200000096663f042d323a9d19c06335abb6318e18e6f8750000000000000000000000000000000000000000">

SELECT dbo.Fred_Table7.ObjectID FROM dbo.Fred_Table7 WHERE (dbo.Fred_Table7.ObjectID not  in (23) AND dbo.Fred_Table7.ObjectID &lt;= 4294966615 AND (dbo.Fred_Table7.LastModifyTime &gt;CAST('2017 10 17 20 08 18 115' AS VARBINARY(32)) OR dbo.Fred_Table7.LastModifyTime =CAST('2017 10 17 20 08 18 115' AS VARBINARY(32)) AND dbo.Fred_Table7.ObjectID &gt; 2404307) AND (dbo.Fred_Table7.SI_INSTANCE_OBJECT = 0 AND dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 0  OR (dbo.Fred_Table7.SI_INSTANCE_OBJECT = 1 OR dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 1)  AND dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 0 AND dbo.Fred_Table7.ScheduleStatus = 1) AND dbo.Fred_Table7.TypeID in (2, 8, 21, 67, 68, 260, 261, 262, 266, 267, 270, 271, 272, 277, 279, 281, 282, 289, 295, 301, 337, 338, 339, 340, 343, 349, 351, 355, 358, 361, 365, 368, 372, 373, 379, 385, 387, 389, 391, 394, 396, 407, 408, 414, 415, 430, 431) AND (SI_PLUGIN_OBJECT = 0) AND dbo.Fred_Table7.SI_HIDDEN_OBJECT = 0) ORDER BY dbo    </frame>

      </executionStack>

      <inputbuf>

SELECT dbo.Fred_Table7.ObjectID FROM dbo.Fred_Table7 WHERE (dbo.Fred_Table7.ObjectID not  in (23) AND dbo.Fred_Table7.ObjectID &lt;= 4294966615 AND (dbo.Fred_Table7.LastModifyTime &gt;CAST('2017 10 17 20 08 18 115' AS VARBINARY(32)) OR dbo.Fred_Table7.LastModifyTime =CAST('2017 10 17 20 08 18 115' AS VARBINARY(32)) AND dbo.Fred_Table7.ObjectID &gt; 2404307) AND (dbo.Fred_Table7.SI_INSTANCE_OBJECT = 0 AND dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 0  OR (dbo.Fred_Table7.SI_INSTANCE_OBJECT = 1 OR dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 1)  AND dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 0 AND dbo.Fred_Table7.ScheduleStatus = 1) AND dbo.Fred_Table7.TypeID in (2, 8, 21, 67, 68, 260, 261, 262, 266, 267, 270, 271, 272, 277, 279, 281, 282, 289, 295, 301, 337, 338, 339, 340, 343, 349, 351, 355, 358, 361, 365, 368, 372, 373, 379, 385, 387, 389, 391, 394, 396, 407, 408, 414, 415, 430, 431) AND (SI_PLUGIN_OBJECT = 0) AND dbo.Fred_Table7.SI_HIDDEN_OBJECT = 0) ORDER BY db   </inputbuf>

    </process>

    <process id="process1b9313868" taskpriority="0" logused="284" waitresource="KEY: 19:72057594041008128 (1679744d2988)" waittime="4168" ownerId="327954910" transactionname="implicit_transaction" lasttranstarted="2017-10-17T17:21:04.417" XDES="0x57788c3a8" lockMode="X" schedulerid="2" kpid="11128" status="suspended" spid="60" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2017-10-17T17:21:04.417" lastbatchcompleted="2017-10-17T17:21:04.417" lastattention="1900-01-01T00:00:00.417" hostpid="4012" loginname="Login1" isolationlevel="read committed (2)" xactid="327954910" currentdb="19" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128058">

      <executionStack>

        <frame procname="adhoc" line="1" stmtstart="86" sqlhandle="0x0200000011d6ca3a9ba3506e8d74888b6554043825c5204e0000000000000000000000000000000000000000">

UPDATE dbo.Fred_Table7 SET Version = @P1, LastModifyTime = @P2 WHERE ObjectID = @P3 AND Version = @P4    </frame>

        <frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">

unknown    </frame>

      </executionStack>

      <inputbuf>

(@P1 int,@P2 varbinary(32),@P3 int,@P4 int)UPDATE dbo.Fred_Table7 SET Version = @P1, LastModifyTime = @P2 WHERE ObjectID = @P3 AND Version = @P4   </inputbuf>

    </process>

  </process-list>

  <resource-list>

    <keylock hobtid="72057594040745984" dbid="19" objectname="Database12.dbo.Fred_Table7" indexname="ObjectID_I7" id="lock52e379a80" mode="X" associatedObjectId="72057594040745984">

      <owner-list>

        <owner id="process1b9313868" mode="X" />

      </owner-list>

      <waiter-list>

        <waiter id="process5776a5498" mode="S" requestType="wait" />

      </waiter-list>

    </keylock>

    <keylock hobtid="72057594041008128" dbid="19" objectname="Database12.dbo.Fred_Table7" indexname="LastModifyTime_I7" id="lock35b41fa80" mode="S" associatedObjectId="72057594041008128">

      <owner-list>

        <owner id="process5776a5498" mode="S" />

      </owner-list>

      <waiter-list>

        <waiter id="process1b9313868" mode="X" requestType="wait" />

      </waiter-list>

    </keylock>

  </resource-list>

</deadlock>

--

You can piece through it to find the <inputbuf> tag to find the queries on the Fred_Table7 that are involved, and find the loginname of Login1, but is this really how you want to consume this data?

https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgK4Lx8DWDZxjWZ9Jbqsovb7iMmL5LpfNuCcOoqdqXDHVHCAZ8vwQPRVTzjnobfpakkhY1nFdXNFysU9LTd_LZWfRAacYVSRw7jIQ3rwWh1If2FOfNGZGtbjTs2ZTO4QlxIhZ-xQE0mKcOJ/s1600/HaHaNo.jpg

A much easier way to deal with this information is in the Deadlock Graph.  

The Deadlock Graph turns the XML information show above into, well, a graph.  You can see the two transactions as the circles on the outside and the two objects involved in the rectangles in the center of the diagram.  Sometimes there are more than two transactions involved in a deadlock (beyond the scope of this post) but if there are more than two they will show up in the graph as well.  When you open the graph in SQL Server Management Studio you can hover over the transaction circle and see the underlying query and some other transaction data.

--

As mentioned above there is a trace event to return the Deadlock Graph, and you can draw it via XEvents as well with a query.

NOTE - there was a change in the way deadlock information is processed in XEvents between SQL Server 2008R2 and SQL Server 2012, so there are different scripts depending on version:

--

/*

SQL Server Deadlock Graph Extraction from Ring Buffer

SQL Server 2008/2008R2

Modified from https://www.sqlservercentral.com/Forums/1399315/System-health-extended-event-session-does-not-capture-latest-deadlocks?PageIndex=1

*/

;WITH SystemHealth

AS (

   SELECT 

      CAST ( target_data AS xml ) AS SessionXML

   FROM 

      sys.dm_xe_session_targets st

   INNER JOIN 

      sys.dm_xe_sessions s 

   ON 

      s.[address] = st.event_session_address

   WHERE 

      name = 'system_health'

)

SELECT 

   Deadlock.value ( '@timestamp', 'datetime' ) AS DeadlockDateTime

,   CAST ( Deadlock.value ( '(data/value)[1]', 'Nvarchar(max)' ) AS XML ) AS DeadlockGraph

FROM 

   SystemHealth s

CROSS APPLY 

   SessionXML.nodes ( '//RingBufferTarget/event' ) AS t (Deadlock)

WHERE 

   Deadlock.value ( '@name', 'nvarchar(128)' ) = N'xml_deadlock_report'

ORDER BY

   Deadlock.value ( '@timestamp', 'datetime' );

--

/*

SQL Server Deadlock Graph Extraction from Ring Buffer

SQL Server 2012+

Modified from https://www.red-gate.com/simple-talk/sql/database-administration/handling-deadlocks-in-sql-server/

*/

SELECT  XEvent.query('(event/data/value/deadlock)[1]') AS DeadlockGraph

FROM    ( SELECT    XEvent.query('.') AS XEvent

          FROM      ( SELECT    CAST(target_data AS XML) AS TargetData

                      FROM      sys.dm_xe_session_targets st

                                JOIN sys.dm_xe_sessions s

                                 ON s.address = st.event_session_address

                      WHERE     s.name = 'system_health'

                                AND st.target_name = 'ring_buffer'

                    ) AS Data

                    CROSS APPLY TargetData.nodes

                  ('RingBufferTarget/event[@name="xml_deadlock_report"]')

                    AS XEventData ( XEvent )

        ) AS src;   

--

Another awesome change in SQL 2012+ is that the System_Health session now writes to a file target as well as the ring buffer memory target.  This is cool because the files persist more data than can be maintained in the ring buffer, giving you more history.  Retrieving data from the XEL files requires a different query, which is set up to dynamically read the XEL files from your default LOG path, wherever it may be:

--

/*

SQL Server Deadlock Graph Extraction from XEL file target

SQL Server 2012+

http://www.sqlservercentral.com/blogs/sql-geek/2017/10/07/extracting-deadlock-information-using-system_health-extended-events/

*/

CREATE TABLE #errorlog (LogDate DATETIME , ProcessInfo VARCHAR(100), [Text] VARCHAR(MAX))

DECLARE @tag VARCHAR (MAX) , @path VARCHAR(MAX);

INSERT INTO #errorlog EXEC sp_readerrorlog;

SELECT @tag = text

FROM #errorlog 

WHERE [Text] LIKE 'Logging%MSSQL\Log%';

DROP TABLE #errorlog;

SET @path = SUBSTRING(@tag, 38, CHARINDEX('MSSQL\Log', @tag) - 29);

SELECT 

CONVERT(xml, event_data).query('/event/data/value/child::*') AS DeadlockReport,

CONVERT(xml, event_data).value('(event[@name="xml_deadlock_report"]/@timestamp)[1]', 'datetime') 

AS Execution_Time

FROM sys.fn_xe_file_target_read_file(@path + '\system_health*.xel', NULL, NULL, NULL)

WHERE OBJECT_NAME like 'xml_deadlock_report';

--

As an example, here is the output of the  ring buffer query versus the file target (XEL) query on a given server:

The file target has six times as much history as the ring buffer (in this case) - you should "always" see the same or more data in the XEL files than the ring buffer.

--

All of these scripts return an XML output like the XML shown above - it doesn't return a graph directly.

https://memegenerator.net/img/instances/71836370/say-whaaat.jpg

To get the graph is pretty straightforward - once you know how.  Open the XML document, either by clicking the link in the resultset or by copy-pasting the XML into the text editor of your choice:

Once the XML document is open, either in Management Studio or in your text editor, simply save the document as extension .XDL rather than .XML  The new file will have an icon like this: 

If you open this file in Management Studio (via double-click or Open>File in Management Studio) you will be presented with the actual Deadlock Graph as seen above, complete with ability to hover to see transaction information, etc. 

...unless you are using SQL Server 2008/2008R2 Management Studio, in which case you will see this:

Argghhhhh!

As described by Extended Events guru Jonathan Kehayias (blog/@sqlpoolboy) in a blog post here, this is an artifact of SQL 2008 Management Studio not being ready to render the deadlock output from XEvents (as opposed to the deadlock output from Trace).  As Jonathan notes there are two ways to handle this - the first way is to use an up-level Management Studio of at least version 2012, either by upgrading the local copy of Management Studio (you can download the current Management Studio that is still compatible back to 2008 from Microsoft here) or by copying the XDL file to another server with a more recent Management Studio.  The other way to open the file under SQL 2008/2008R2 is to use SentryOne's free tool Plan Explorer Pro.  I usually don't pitch company products but this is a really useful 100% free tool.

The most common answer will be the first - copy the XDL to a server with 2012+ Management Studio, and all will be well.

--

UPDATE - a friend pointed out that I had forgotten a script that does a great job shredding the Deadlock information from files, the ring buffer, or SentryOne's data collection into a useful format.  It was created by MCM/MVP Wayne Sheffield (blog/@DBAWayne) and is located here.

--

Hope this helps!

Finding File Growths with Extended Events

I give a SQLSaturday session called "Introduction to Extended Events" and at a recent presentation I had a pair of attendees ask me afterwards for a more "real world" example.  I had a basic demo in my session showing setting up a session with a predicate filter to pull particular events for a single database, but it didn't really show using XEvents to solve a business problem.

I pondered for a while and decided to try to recreate something I normally do with the default trace.  The obvious example to me was pulling data on file growths.

What?  You didn't know you could pull information about file growths from the default trace?

http://canitbesaturdaynow.com/images/fpics/1137/kitty_-(8)__large.jpg

I discovered this some time ago when I needed to find out why a database was blowing up at 1am without needing to be awake and online at 1am...at first I was going to set up a manual trace when I found a pair of blog posts that helped me out.

The first was "Did we have recent autogrows?" from Tibor Karazi (blog/@TiborKaraszi) which clued me in to the fact that autogrow information is even in the default trace.  The catch to Tibor's query is that it relied on a specific trc file - the default trace is a rollover structure so at any given time there are usually multiple sequential trc files, and using his query meant I needed to run it, edit the file name, run it again, etc.

The next piece was the Simple Talk article "Collecting the Information in the Default Trace" from Feodor Georgiev (blog/@FeodorGeorgiev) that showed me how to dynamically build the log file path *and* the fact that I could simply reference log,trc (instead of log_123.trc) and the function would concatenate all of the trc files into a single resultset.

I have said it before and I will say it again - when you need help, odds are someone else has already solved the same (or a similar) problem - look around and you will probably find it!  When you save or reference someone else's work, always make sue to give credit (as I have done above) - even if you make modifications to code or ideas, always acknowledge the original material.

http://www.funcatpictures.com/wp-content/uploads/2013/10/funny-cat-pics-internet-high-five.jpg

I took the two queries I found and combined them into a single modified query that used Tibor's base query to pull autogrowths but Feodor's concept of the custom built log path:

/*
Default Trace AutoGrow Query

Modified from Tibor Karazi
http://sqlblog.com/blogs/tibor_karaszi/archive/2008/06/19/did-we-have-recent-autogrow.aspx
and Feodor Georgiev
https://www.simple-talk.com/sql/database-administration/collecting-the-information-in-the-default-trace/
*/

DECLARE @df bit
SELECT @df = is_default FROM sys.traces WHERE id = 1
IF @df = 0 OR @df IS NULL
BEGIN
  RAISERROR('No default trace running!', 16, 1)
  RETURN
END
SELECT te.name as EventName
, t.DatabaseName
, t.FileName
, t.StartTime
, t.ApplicationName
, HostName
, LoginName
, Duration
, TextData
FROM fn_trace_gettable(
(SELECT REVERSE(SUBSTRING(REVERSE(path), CHARINDEX('\', REVERSE(path)),256)) + 'log.trc'
FROM    sys.traces
WHERE   is_default = 1
), DEFAULT) AS t
INNER JOIN sys.trace_events AS te
ON t.EventClass = te.trace_event_id
WHERE 1=1
and te.name LIKE '%Auto Grow'
--and DatabaseName='tempdb'
--and StartTime>'05/27/2014'
ORDER BY StartTime

--

SELECT TOP 1 'Oldest StartTime' as Label, t.StartTime
FROM fn_trace_gettable(
(SELECT REVERSE(SUBSTRING(REVERSE(path), CHARINDEX('\', REVERSE(path)),256)) + 'log.trc'
FROM    sys.traces
WHERE   is_default = 1
), DEFAULT) AS t
INNER JOIN sys.trace_events AS te
ON t.EventClass = te.trace_event_id
ORDER BY StartTime   

The top query returns all rows for an event like '%Auto Grow' (to capture DATA and LOG autogrowths) and as you can see you can also filter on a specific database, date range, etc.

The second query simply uses the same base table set to return the datetime of the oldest row in the current default trace.  Since the default trace is a rolling first in first out (FIFO) arrangement, there is no way to definitively say how far back the trace goes other than to actually look in the trace like this.  If you have a lot of trace-relevant events or a lot of service restarts, your default trace may only have a few days (or even hours) of data and not have what you need - for example if you are trying to troubleshoot a problem from last Saturday and by Monday it has already aged out of the trace, then this isn't useful.

The resultset looks like this:

Pretty slick, right?

http://i.imgur.com/vIdCPPt.png

...but what does this have to do with Extended Events?

As I started out, I was looking for something slick I do with a trace that I could replicate in Extended Events, and this was a great candidate.

--

The catch as I discovered, is that while file growths are captured in the default trace, they are *not* in the system health session...

http://www.wicproject.com/images/2010/05/hobbes_doh.jpg

This was slightly annoying, but it also gave me an excuse to create a demo for setting up an XEvents session :)

--

First, the session:

USE [master]
GO 

SET NOCOUNT ON 

/* Create Extended Events Session */
IF EXISTS (SELECT 1 FROM master.sys.server_event_sessions WHERE name = 'DemoFileSize')
DROP EVENT SESSION [DemoFileSize] ON SERVER
GO
CREATE EVENT SESSION [DemoFileSize] ON SERVER
ADD EVENT sqlserver.database_file_size_change(SET collect_database_name=(1)
    ACTION(package0.collect_system_time,sqlos.task_time,
sqlserver.client_app_name,sqlserver.client_hostname,
sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,
sqlserver.server_instance_name,sqlserver.session_id,
sqlserver.sql_text,sqlserver.username)),
/* Note - no predicate/filter - will collect *all* DATA file size changes */
ADD EVENT sqlserver.databases_log_file_size_changed(
    ACTION(package0.collect_system_time,sqlos.task_time,
sqlserver.client_app_name,sqlserver.client_hostname,
sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,
sqlserver.server_instance_name,sqlserver.session_id,
sqlserver.sql_text,sqlserver.username))
/* Note - no predicate/filter - will collect *all* LOG file size changes */
ADD TARGET package0.event_file(SET filename=N'c:\XE\DemoFileSize.xel',
max_file_size=(500),max_rollover_files=(10))
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=ON)
GO

ALTER EVENT SESSION [DemoFileSize] ON SERVER
STATE = START;
GO

This just creates a basic session, tracking two events, sqlserver.database_file_size_change and sqlserver.log_file_size_change, writing the output to a file target.

--

Next the database and table:

/* Create DemoGrowth database, dropping any existing DemoGrowth database */
IF EXISTS (SELECT database_id from sys.databases WHERE name = 'DemoGrowth')
BEGIN
 ALTER DATABASE [DemoGrowth] SET SINGLE_USER WITH ROLLBACK IMMEDIATE
 DROP DATABASE [DemoGrowth]
END
CREATE DATABASE [DemoGrowth]
 ON  PRIMARY
( NAME = N'DemoGrowth_Data'
 , FILENAME = 'C:\Temp\DemoGrowth.MDF'
 , SIZE = 4MB , MAXSIZE = UNLIMITED, FILEGROWTH = 2MB )
 /* Small increments for maximum autogrowths */
 LOG ON
( NAME = N'DemoGrowth_log'
 , FILENAME = 'C:\Temp\DemoGrowth.LDF'
 , SIZE = 2MB , MAXSIZE = 2048GB , FILEGROWTH = 2MB )

ALTER DATABASE [DemoGrowth] SET RECOVERY FULL
GO

BACKUP DATABASE [DemoGrowth]
TO DISK = 'C:\TEMP\DemoGrowth.bak'
WITH STATS = 5, INIT

USE [DemoGrowth]
GO

/* Create DemoGrow table, dropping any existing DemoGrow table */
IF OBJECT_ID('dbo.DemoGrow','U') is not null
DROP TABLE dbo.DemoGrow
CREATE TABLE dbo.DemoGrow
/* Purposely large datatypes for maximum needed autogrowths */
(
ID BIGINT IDENTITY(1,1)
,BIGNAME NCHAR(4000) DEFAULT 'BOB'
)

Setting the table with an identity and a character column with a default value makes the test inserts straightforward to code.  The database was created small and the table with large datatypes in order to maximize potential auto-growths.

--

The next step is to Watch Live Data for the session in order to see that autogrowths are happening - note that the sessions as configured is set to write to an event_file target, so Watch Live Data is the easy way to watch events happen, albeit with some minor performance impact.

Next, let's insert some rows and see what happens:

/* Insert 6000 rows and return file sizes before and after inserts */
SELECT name, size*8.0/1024.0 as SizeMB from DemoGrowth.sys.sysfiles 

GO

INSERT INTO dbo.Grow DEFAULT VALUES 

GO 6000 

SELECT count(ID) from dbo.Grow (NOLOCK) 

SELECT name, size*8.0/1024.0 as SizeMB from DemoGrowth.sys.sysfiles
/* If after sizes <> before sizes, check Watch Live Data for rows */

The sysfiles query shows whether the data and log files have grown after the inserts - it is possible (although highly unlikely) that the 6000 inserts don't cause either file to grow - if this is the case (or if you just want to witness more traffic) you re-run the code block multiple times.

--

Next we need to backup the LOG (remember that we are in FULL recovery) and manually shrink the database in order to see that the shrink also causes events:

BACKUP LOG DemoGrowth
TO DISK = 'C:\TEMP\DemoGrowth.trn'
WITH STATS = 5, INIT
/* Shrink files and return sizes before and after */

SELECT name, size*8.0/1024.0 as SizeMB from DemoGrowth.sys.sysfiles 

DBCC SHRINKFILE (N'DemoGrowth_Data')
GO

DBCC SHRINKFILE (N'DemoGrowth_Log')
GO

SELECT name, size*8.0/1024.0 as SizeMB from DemoGrowth.sys.sysfiles

/* Assuming shrink occurs, check Watch Live Data for rows */
/* If the LOG doesn't show shrunk, then re-run LOG backup and shrink again */

Just as a shrink logs events, so do manual growths:

/* Manually grow DATA file to see effect on session */
SELECT name, size*8.0/1024.0 as SizeMB from DemoGrowth.sys.sysfiles

/* Check Current File Size to set an appropriate size in ALTER grow statement */
ALTER DATABASE [DemoGrowth] MODIFY FILE ( NAME = N'DemoGrowth_Data', SIZE = 128MB )
GO

SELECT name, size*8.0/1024.0 as SizeMB from DemoGrowth.sys.sysfiles
/* Check Watch Live Data for rows */

--

So what is in the event_file (XEL file)?  There is a system function (sys.fn_xe_file_target_read_file) to return that data:

/* So let's look at the XEL file */
SELECT * FROM sys.fn_xe_file_target_read_file('C:\temp\DemoFileSize*.xel',NULL, NULL, NULL);  

BLEAH!

As always, someone has already come up with a better solution.  Google brought me to SQL Zealot and his query to shred the XML at https://sqlzealots.com/2015/04/01/auto-file-growth-track-the-growth-events-using-extended-events-in-sql-server/  - I modified the query slightly to return the data elements I wanted, including the timestamp:

SELECT
Case when file_type = 'Data file' Then 'Data File Grow' Else File_Type End AS [Event Name]
, database_name AS DatabaseName
, dateadd(minute, datediff(minute, sysutcdatetime(), sysdatetime()), timestamp1) as LocalTimeStamp
/* added the timestamp and in XE is UTC - this code converts it to local server time zone */
, file_names
, size_change_mb
, duration
, client_app_name AS Client_Application
, client_hostname
, session_id AS SessionID
, Is_Automatic
FROM
(
SELECT
(n.value ('(data[@name="size_change_kb"]/value)[1]', 'int')/1024.0) AS size_change_mb
, n.value('(@timestamp)[1]', 'datetime2') as timestamp1
, n.value ('(data[@name="database_name"]/value)[1]', 'nvarchar(50)') AS database_name
, n.value ('(data[@name="duration"]/value)[1]', 'int') AS duration
, n.value ('(data[@name="file_type"]/text)[1]','nvarchar(50)') AS file_type
, n.value ('(action[@name="client_app_name"]/value)[1]','nvarchar(50)') AS client_app_name
, n.value ('(action[@name="session_id"]/value)[1]','nvarchar(50)') AS session_id
, n.value ('(action[@name="client_hostname"]/value)[1]','nvarchar(50)') AS Client_HostName
, n.value ('(data[@name="file_name"]/value)[1]','nvarchar(50)') AS file_names
, n.value ('(data[@name="is_automatic"]/value)[1]','nvarchar(50)') AS Is_Automatic
FROM
(
SELECT CAST(event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file(
N'C:\temp\DemoFileSize*.xel'
, NULL
, NULL
, NULL
)
) AS Event_Data_Table
CROSS APPLY event_data.nodes('event') AS q(n)) xyz
ORDER BY timestamp1 desc
/* Much Better! */

--

So as you can see, a basic XEvents session provides the information comparable to the default trace.

But....XEvents is supposed to be better right?

I neglected to tell you one thing...in the query above you can see that there is a data element for sql_text - look what's in it:

INSERT INTO dbo.DemoGrow DEFAULT VALUES

http://s.quickmeme.com/img/15/151d67b9a73228d44b1bfabea0d012b54b9cd2821a25bf4b4be1bad10c41a95d.jpg

Pretty slick, huh?  The element shows you *what query* caused the file size change - something the default trace does not.  If you go back to the default trace, you will see there is a textData field, but that field is NULL for all of the operations in question (it is used for a few other types of events such as DBCC events, but not for the file growth events).

Also you may have noticed that our XEvents are called sqlserver.database_file_size_change and sqlserver.log_file_size_change, and they return data for growths *and* shrinks.  The default trace only returns data on file growths directly (although you could scrape the "DBCC Events" looking for DBCC SHRINKDATABASE and DBCC SHRINKFILE, but there are a lot of other DBCC events to search through.

--

Extended Events are awesome, and with a little work can give you everything that trace gives you and so much more.

Hope this helps!

T-SQL Tuesday #74 - Who Grew The Database?

This month T-SQL Tuesday is hosted by Robert Davis (blog/@SQLSoldier) and his topic of choice is “Be The Change”

(If you don’t know about T-SQL Tuesday check out the information here – each month there is a new topic and it is a great excuse to write each month (and to start writing!) because someone offers a topic, so you already have taken the first step!).

--

Robert's choice of topics threw me:

The topic for T-SQL Tuesday #74 is Be the Change. More specifically, data changes. How do you track changing data? How do you do your ETL? How do you clean or scrub your data? Anything related to changing data. Give us your most interesting post involving changing data next Tuesday, January 12, 2016.

As a mostly operational DBA, I have very limited contact with data changes and tracking them.  I have some very limited experience with Change Data Capture, but others have already written about it and done a very good job (also - read Mickey Stuewe's (blog/@SQLMickey) post "Knowing When Data Changes Occur in Standard Edition" about how to work around CDC being Enterprise Only!)

I had a breakthrough earlier today reading Jason Brimhall's (blog/@sqlrnnr) post "All about the Change" in which he writes about changes as related to SQL Audit.  I realized that a fair amount of the administrative triage that I do is directly caused by data changes, especially large scale ones. Here is a solution that I have modified over the years to help me track the changes in my systems *caused* by data changes.  (see how I spun that?)

--

The changes in question here are file size changes - as operational DBAs one of the problems we constantly deal with is files that grow out of control, often from maintenance work such as index rebuilds or from unusual ad-hoc operations such as the analyst working at 1am trying to create a personal copy of the giant Sales table.

We all know that the "best" thing to do (remember, #ItDepends) is to appropriately size your DATA and LOG files ahead of time, and if possible to manually grow those files after hours so that there isn't any production impact.  Even in this absolute best case (almost theoretical) scenario, it is still usually right to leave auto-growth enabled "just in case."

Very few of us live in that world, and we size our files as best as we can with almost no real business requirements using our DBA "Spidey Sense."  Our files are then "managed by auto-grow" as we try to find the best steady state for the DATA and LOG files and minimize impact while getting the best performance.

Does that sound familiar?

http://cdn.meme.am/instances/53655925.jpg

As a service provider, we monitor the drive free space and SQL Server Error Logs on our client servers (along with dozens of other things) - auto-growth problems can often be seen through messages like this:

Could not allocate space for object 'dbo.Table1'.'PK_Table1' in database 'myDatabase' because the 'PRIMARY' filegroup is full. Create disk space by deleting unneeded files, dropping objects in the filegroup, adding additional files to the filegroup, or setting autogrowth on for existing files in the filegroup.

...or...

The transaction log for database 'SomeOtherDatabase' is full due to 'ACTIVE_TRANSACTION'.

These messages usually mean that either the file has hit its MAXSIZE cap or that the drive hosting the file is full (or at least sufficiently full that it can't hold another FILEGROWTH increment worth of space). The first question that comes up in the root cause analysis is often "Who grew the database?"

Sometimes there are obvious culprits - is an index maintenance job running?  Is there a nightly ETL running that had an exceptionally large file last night?  Often there is no such smoking gun...and then you need something more.

--

I feel a little dirty writing about the Default Trace in the world of Extended Events, but I also know that many people simply don't know how to use XEvents, and this can be faster if you already have it in your toolbox.  Also it will work back to SQL 2005 where XEvents were new in SQL 2008.

I have modified this several times to improve it - I started with a query from Tibor Karaszi (blog/@TiborKaraszi), modified it with some code from Jason Strate (blog/@StrateSQL), and then modified that myself for what is included and what is filtered.  There are links to both Tibor's and Jason's source material in the code below.

--

/*

Default Trace Query

Especially useful for Auto Grow and Shrink Events 
but works for all default trace info

Modified from Tibor Karaszi at 
http://sqlblog.com/blogs/tibor_karaszi/archive/2008/06/19/did-we-have-recent-autogrow.aspx 

Default Trace Path query modified from
http://www.jasonstrate.com/2013/01/determining-default-trace-location/

*/

DECLARE @fn VARCHAR(1000), @df bit
SELECT @fn =REVERSE(SUBSTRING(REVERSE(path),CHARINDEX('\',REVERSE(path)),LEN(path)))+'log.trc',
/* reading log.trc instead of a specific file will query all current log files */
@df = is_default 
FROM sys.traces 
WHERE id = 1

IF @df = 0 OR @df IS NULL
BEGIN
  RAISERROR('No default trace running!', 16, 1)
  RETURN
END

SELECT te.name as EventName
, t.DatabaseName
, t.FileName
, t.TextData
, t.StartTime
, t.EndTime
, t.ApplicationName
, HostName
, LoginName
, Duration
, cast(Duration/1000000.0 as decimal(10,2)) as DurationSeconds
FROM fn_trace_gettable(@fn, DEFAULT) AS t  
INNER JOIN sys.trace_events AS te 
ON t.EventClass = te.trace_event_id  
WHERE 1=1 /* necessary to cleanly build WHERE clause */
/* find autogrowth events */ 
--and te.name LIKE '%grow%'
/* find autoshrink events */ 
--and te.name LIKE '%shrink%'
/* find manual shrink events */ 
--and (te.name = 'Audit DBCC Event' and (TextData like '%shrinkfile%' or TextData like '%shrinkdatabase%'))
--and DatabaseName='tempdb'
--and StartTime>'01/10/2016 00:00'
--and EndTime<='01/11/2016 13:00'
ORDER BY StartTime desc  

--

The base query pulls all events from the Default Trace.  As noted in the Variable assignment query from @fn, reading data from log.trc (rather than log_05.trc or log_44.trc for example) will combine the rows in the five current default trace TRC files.

The WHERE clause is built so that you can uncomment whichever lines you need.  The initial 1=1 is present so that all of the commented out lines can start with an 'AND' to allow them to flow together regardless of which lines you uncomment.

Want to find autogrowth events for the Bob database?  Uncomment the "and te.name like '%grow%' and the "and DatabaseName='Bob'" lines and you are set!  Need to add time filters?  Uncomment out those lines and modify the times.  And so on....

If you run the query, you can see that the autogrowth of Bob was caused by application "Sales" running on AppServer01, or by a .NET application on WebServer99 running as Domain\WebUser, or even by SQLCMD running on the server locally as the Agent service account (in my world this often means the growth is being caused by a Hallengren maintenance job, since his SQL Agent jobs run under SQLCMD).

--

Remember, this can be done via XEvents as well (a topic for another blog post) and since Trace is deprecated that is the "better" way to do this - but this still works and is quick to use.

Hope this helps!