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.