Incorrect Timestamp on Events in Extended Events

Last week, Denny Cherry (Blog|Twitter) asked why the timestamp on the events he was collecting using Extended Events in SQL Server 2008 was incorrect.  I’ve seen this a couple of times on the MSDN Forums, and its come up a couple of times in discussions with other MVP’s about Extended Events.  According to a feedback item I found on Connect for this problem, this is a bug that has been addressed and will be in SQL Server 2008 R2 SP1, and I can only assume a Cumulative Update for SQL Server 2008 that is released in the future as well. 

At the time that Denny asked about this, I happened to have a virtual machine on my laptop that had been running and suspended for a couple of months and I was able to see the issue occurring on it.  Up until this point I had never actually seen the issue occur personally, but with this virtual machine I was able to play around with a event session to see if there was anyway to work around this problem.  I started off with a basic event session that collected the sqlserver.sql_statement_starting event and then added different actions to it to see what other information was available.  I hit pay dirt with the package0.collect_system_time action which reported the correct datetime value in UTC for the events, even when the event timestamp was incorrect as shown in the following eventdata xml:

<event name="sql_statement_starting" package="sqlserver" timestamp="2011-03-04T15:56:30.612Z">
  <data name="state">
    <type name="statement_starting_state" package="sqlserver" />
    <value>0</value>
    <text>Normal</text>
  </data>
  <data name="line_number">
    <type name="int32" package="package0" />
    <value>6</value>
  </data>
  <data name="offset">
    <type name="int32" package="package0" />
    <value>130</value>
  </data>
  <data name="offset_end">
    <type name="int32" package="package0" />
    <value>-1</value>
  </data>
  <data name="statement">
    <type name="unicode_string" package="package0" />
    <value>SELECT @@VERSION</value>
  </data>
  <action name="collect_system_time" package="package0">
    <type name="filetime" package="package0" />
    <value>2011-03-16T00:58:13.792Z</value>
  </action>
</event>

This is a fairly insidious bug that affects every event session on the server, including the default system_health session that is running on every SQL Server 2008 instance.  Unlike the default trace in SQL Server, the Extended Events system_health session can be modified to change the information that is being collected.  While I would not change the events or predicates, I would add the sqlserver.collect_system_time action to each of the events so that if you need information from the system_health session, you know when an event actually fired.  The script for the system_health session is available in the utables.sql script file that is in the Install folder under the instance root for each instance of SQL Server.  Using this as a base you can easily modify it as follows to add the additional action to each event.

— Extended events default session
IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name=’system_health’)
    DROP EVENT SESSION system_health ON SERVER
GO
— The predicates in this session have been carefully crafted to minimize impact of event collection
— Changing the predicate definition may impact system performance

CREATE EVENT SESSION system_health ON SERVER
ADD EVENT sqlserver.error_reported
(
    ACTION (package0.callstack, sqlserver.session_id, sqlserver.sql_text, sqlserver.tsql_stack, package0.collect_system_time)
    — Get callstack, SPID, and query for all high severity errors ( above sev 20 )
    WHERE severity >= 20
    — Get callstack, SPID, and query for OOM errors ( 17803 , 701 , 802 , 8645 , 8651 , 8657 , 8902 )
    OR (error = 17803 OR error = 701 OR error = 802 OR error = 8645 OR error = 8651 OR error = 8657 OR error = 8902)
),
ADD EVENT sqlos.scheduler_monitor_non_yielding_ring_buffer_recorded
(
    ACTION (package0.collect_system_time)
),
ADD EVENT sqlserver.xml_deadlock_report
(
    ACTION (package0.collect_system_time)
),
ADD EVENT sqlos.wait_info
(
    ACTION (package0.callstack, sqlserver.session_id, sqlserver.sql_text, package0.collect_system_time)
    WHERE
    (duration > 15000 AND
        (   
            (wait_type > 31    — Waits for latches and important wait resources (not locks ) that have exceeded 15 seconds.
                AND
                (
                    (wait_type > 47 AND wait_type < 54)
                    OR wait_type < 38
                    OR (wait_type > 63 AND wait_type < 70)
                    OR (wait_type > 96 AND wait_type < 100)
                    OR (wait_type = 107)
                    OR (wait_type = 113)
                    OR (wait_type > 174 AND wait_type < 179)
                    OR (wait_type = 186)
                    OR (wait_type = 207)
                    OR (wait_type = 269)
                    OR (wait_type = 283)
                    OR (wait_type = 284)
                )
            )
            OR
            (duration > 30000        — Waits for locks that have exceeded 30 secs.
                AND wait_type < 22
            )
        )
    )
),
ADD EVENT sqlos.wait_info_external
(
    ACTION (package0.callstack, sqlserver.session_id, sqlserver.sql_text, package0.collect_system_time)
    WHERE
    (duration > 5000 AND
        (  
            (    — Login related preemptive waits that have exceeded 5 seconds.
                (wait_type > 365 AND wait_type < 372)
                OR (wait_type > 372 AND wait_type < 377)
                OR (wait_type > 377 AND wait_type < 383)
                OR (wait_type > 420 AND wait_type < 424)
                OR (wait_type > 426 AND wait_type < 432)
                OR (wait_type > 432 AND wait_type < 435)
            )
            OR
            (duration > 45000     — Preemptive OS waits that have exceeded 45 seconds.
                AND
                (   
                    (wait_type > 382 AND wait_type < 386)
                    OR (wait_type > 423 AND wait_type < 427)
                    OR (wait_type > 434 AND wait_type < 437)
                    OR (wait_type > 442 AND wait_type < 451)
                    OR (wait_type > 451 AND wait_type < 473)
                    OR (wait_type > 484 AND wait_type < 499)
                    OR wait_type = 365
                    OR wait_type = 372
                    OR wait_type = 377
                    OR wait_type = 387
                    OR wait_type = 432
                    OR wait_type = 502
                )
            )
        )
    )
)
ADD TARGET package0.ring_buffer        — Store events in the ring buffer target
    (SET MAX_MEMORY = 4096)
WITH (STARTUP_STATE = ON);
GO

When the fix for this bug is released in SQL Server, the customization of the system_health event session can be undone by running the original script in the utables.sql file, which will revert the event session configuration back to its default.

Sanitizing Execution Plans using Powershell

A few weeks ago I tweeted a couple of images showing a really nasty execution plan in SQL Sentry’s free Plan Explorer tool being displayed on a 65 inch touch screen LCD monitor.

Large Plan Explorer Plan Large Plan Explorer Plan2

 

I’ve been using Plan Explorer to look at execution plans since its early beta’s, when it was known as Plan Viewer, after seeing a demo of Performance Advisor v6 by Greg Gonzalez (Blog|Twitter).  During the beta I provided a lot of feed back to Greg and I pushed the tool to its limits a couple of times with some of the nasty execution plans I had.  In the case of the plan shown above, Management Studio falls to its knees trying to manage the plan, and is everything except useful when the plan is open, but Plan Explorer handles it without a hitch.

After posting these images and getting some comments, I began to realize how useful this type of plan could be in doing demo’s of the tool, but one of the problems with an execution plan is that it contains a lot of very specific information about the database structures and code that could be considered intellectual property.  It is possible to retain the integrity of the plan structure, and what it shows, while removing all of the object and statement information from the plan by replacing them with meaningless values.  During the beta’s I did this a couple of times when I came across an issue, or thought of a useful feature, but it was always a painstaking manual process.  This time I set out to do it with Powershell by parsing the XML Showplan and performing replace operations on the XML nodes. 

Loading the XML Showplan from a .sqlplan file is relatively straightforward, and I’ve done quite a bit of plan shredding in the past, so I thought this would be a very simple task to complete.  It turns out that I had a bit to learn about processing XML in .NET and by extension Powershell.  The first problem I encountered was how to use the ShowPlan XmlNamespace so that I could shred the document to find the elements of interest.  This is accomplished using the XmlNamespaceManager in .NET.

#Setup the XmlNamespaceManager and add the ShowPlan Namespace to it.

$nsMgr = new-object 'System.Xml.XmlNamespaceManager' $xml.NameTable;

$nsMgr.AddNamespace("sm", "http://schemas.microsoft.com/sqlserver/2004/07/showplan");

The SelectNodes() method of the .NET XmlDocument is overloaded and accepts an XPath and XmlNamespaceManager to determine the nodes to select from the XmlDocument.  With the correct nodes selected replacing the information as easy as setting a new value for the the element of interest.

#Replace the StatementText for all statements

$xml.SelectNodes("//sm:StmtSimple", $nsMgr) | % {

$_.StatementText = "–Statement text stripped by ExecutionPlanSanitizer Powershell Script (http://www.sqlskills.com/blogs/jonathan)" } 

The attached Powershell script replaces the statements, database names, object names, index names, non-dbo schema names,  and column names of the input file and then writes the new plan to an output file that still conforms to the schema and can be shared without sharing intellectual property.

ExecutionPlanSanitizer.ps1 (3.26 kb)