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.

11 thoughts on “Incorrect Timestamp on Events in Extended Events

  1. Looks like the collect_system_time action is in package0 (SQL Server 2008 SP3).

    name object_type name
    collect_system_time action package0

    Thanks

  2. This post has been spammed repeatedly by anonymous comments. If you expect your comment to be replied to kindly post it with a valid email address and name and then email me through the Email Jonathan link above and I will happily approve the comment and reply to it. Otherwise it will be caught by our SPAM filters and won’t be posted. Sorry for the inconvenience, but these steps are necessary to maintain the integrity of the comments being posted here.

      1. Looking at this further, maybe it is “fixed” but shows UTC/GMT regardless of the servers time zone?
        Even adding sqlserver.sql_batch_completed(ACTION (package0.collect_system_time… seemed to be UTC.
        As long as this proves to the case and is consistent I can just dateadd to get what I need.

  3. It’s September 2020, and I’m having the same problem on an old server I am working to replace! I scabbed Jonathen’s code and added to this query of the EE.

    SELECT
    –The formatting of Event_time is needed because of bug where timestamp is in UTC. See https://www.sqlskills.com/blogs/jonathan/incorrect-timestamp-on-events-in-extended-events/
    DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), CAST(event_data AS XML).value(N'(event/@timestamp)[1]’, N’datetime’)) AS Event_time,
    object_name,
    file_name,
    file_offset,
    event_data,
    CAST(event_data AS XML) AS [event_data_XML]
    FROM
    sys.fn_xe_file_target_read_file(
    ‘.xel’,
    null, null, null )

    1. The timestamp is ALWAYS in UTC. That’s not the same as the bug that existed where the timestamp was actually incorrect for events by days to even weeks depending on how long the server has been running.

Leave a Reply

Your email address will not be published. Required fields are marked *

Other articles

Imagine feeling confident enough to handle whatever your database throws at you.

With training and consulting from SQLskills, you’ll be able to solve big problems, elevate your team’s capacity, and take control of your data career.