{"id":530,"date":"2011-03-21T11:50:19","date_gmt":"2011-03-21T11:50:19","guid":{"rendered":"\/blogs\/jonathan\/post\/Incorrect-Timestamp-on-Events-in-Extended-Events.aspx"},"modified":"2017-04-13T12:12:25","modified_gmt":"2017-04-13T16:12:25","slug":"incorrect-timestamp-on-events-in-extended-events","status":"publish","type":"post","link":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/","title":{"rendered":"Incorrect Timestamp on Events in Extended Events"},"content":{"rendered":"

Last week, Denny Cherry (Blog<\/a>|Twitter<\/a>) asked why the timestamp on the events he was collecting using Extended Events in SQL Server 2008 was incorrect<\/a>.  I\u2019ve seen this a couple of times on the MSDN Forums, and its come up a couple of times in discussions with other MVP\u2019s about Extended Events.  According to a feedback item I found on Connect<\/a> 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.  <\/p>\n

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:<\/p>\n

\n

<event name="sql_statement_starting" package="sqlserver" timestamp="2011-03-04T15:56:30.612Z<\/font>">
  <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<\/font><\/value>
  <\/action>
<\/event> <\/p>\n<\/blockquote>\n

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.<\/p>\n

\n

— 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<\/p>\n<\/blockquote>\n

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.<\/p>\n","protected":false},"excerpt":{"rendered":"

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\u2019ve seen this a couple of times on the MSDN Forums, and its come up a couple of times in discussions with other MVP\u2019s about Extended Events.  According to a feedback […]<\/p>\n","protected":false},"author":4,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[23,38],"tags":[],"class_list":["post-530","post","type-post","status-publish","format-standard","hentry","category-extended-events","category-sql-server-2008"],"yoast_head":"\nIncorrect Timestamp on Events in Extended Events - Jonathan Kehayias<\/title>\n<meta name=\"robots\" content=\"index, follow, max-snippet:-1, max-image-preview:large, max-video-preview:-1\" \/>\n<link rel=\"canonical\" href=\"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/\" \/>\n<meta property=\"og:locale\" content=\"en_US\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"Incorrect Timestamp on Events in Extended Events - Jonathan Kehayias\" \/>\n<meta property=\"og:description\" content=\"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\u2019ve seen this a couple of times on the MSDN Forums, and its come up a couple of times in discussions with other MVP\u2019s about Extended Events.  According to a feedback […]\" \/>\n<meta property=\"og:url\" content=\"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/\" \/>\n<meta property=\"og:site_name\" content=\"Jonathan Kehayias\" \/>\n<meta property=\"article:published_time\" content=\"2011-03-21T11:50:19+00:00\" \/>\n<meta property=\"article:modified_time\" content=\"2017-04-13T16:12:25+00:00\" \/>\n<meta name=\"author\" content=\"Jonathan Kehayias\" \/>\n<meta name=\"twitter:label1\" content=\"Written by\" \/>\n\t<meta name=\"twitter:data1\" content=\"Jonathan Kehayias\" \/>\n\t<meta name=\"twitter:label2\" content=\"Est. reading time\" \/>\n\t<meta name=\"twitter:data2\" content=\"5 minutes\" \/>\n<script type=\"application\/ld+json\" class=\"yoast-schema-graph\">{\"@context\":\"https:\\\/\\\/schema.org\",\"@graph\":[{\"@type\":\"Article\",\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/incorrect-timestamp-on-events-in-extended-events\\\/#article\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/incorrect-timestamp-on-events-in-extended-events\\\/\"},\"author\":{\"name\":\"Jonathan Kehayias\",\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/#\\\/schema\\\/person\\\/01c10d94f3648654ef706d5e6305f69c\"},\"headline\":\"Incorrect Timestamp on Events in Extended Events\",\"datePublished\":\"2011-03-21T11:50:19+00:00\",\"dateModified\":\"2017-04-13T16:12:25+00:00\",\"mainEntityOfPage\":{\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/incorrect-timestamp-on-events-in-extended-events\\\/\"},\"wordCount\":1081,\"commentCount\":13,\"articleSection\":[\"Extended Events\",\"SQL Server 2008\"],\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"CommentAction\",\"name\":\"Comment\",\"target\":[\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/incorrect-timestamp-on-events-in-extended-events\\\/#respond\"]}]},{\"@type\":\"WebPage\",\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/incorrect-timestamp-on-events-in-extended-events\\\/\",\"url\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/incorrect-timestamp-on-events-in-extended-events\\\/\",\"name\":\"Incorrect Timestamp on Events in Extended Events - Jonathan Kehayias\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/#website\"},\"datePublished\":\"2011-03-21T11:50:19+00:00\",\"dateModified\":\"2017-04-13T16:12:25+00:00\",\"author\":{\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/#\\\/schema\\\/person\\\/01c10d94f3648654ef706d5e6305f69c\"},\"breadcrumb\":{\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/incorrect-timestamp-on-events-in-extended-events\\\/#breadcrumb\"},\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/incorrect-timestamp-on-events-in-extended-events\\\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/incorrect-timestamp-on-events-in-extended-events\\\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Home\",\"item\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"Extended Events\",\"item\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/category\\\/extended-events\\\/\"},{\"@type\":\"ListItem\",\"position\":3,\"name\":\"Incorrect Timestamp on Events in Extended Events\"}]},{\"@type\":\"WebSite\",\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/#website\",\"url\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/\",\"name\":\"Jonathan Kehayias - The Rambling DBA\",\"description\":\"The Rambling DBA\",\"potentialAction\":[{\"@type\":\"SearchAction\",\"target\":{\"@type\":\"EntryPoint\",\"urlTemplate\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/?s={search_term_string}\"},\"query-input\":{\"@type\":\"PropertyValueSpecification\",\"valueRequired\":true,\"valueName\":\"search_term_string\"}}],\"inLanguage\":\"en-US\"},{\"@type\":\"Person\",\"@id\":\"https:\\\/\\\/www.sqlskills.com\\\/blogs\\\/jonathan\\\/#\\\/schema\\\/person\\\/01c10d94f3648654ef706d5e6305f69c\",\"name\":\"Jonathan Kehayias\",\"image\":{\"@type\":\"ImageObject\",\"inLanguage\":\"en-US\",\"@id\":\"https:\\\/\\\/secure.gravatar.com\\\/avatar\\\/86630e27f5deecc5c393ea57fc7c3b6a068949f4fd6b5309f81de5a276f12855?s=96&d=mm&r=g\",\"url\":\"https:\\\/\\\/secure.gravatar.com\\\/avatar\\\/86630e27f5deecc5c393ea57fc7c3b6a068949f4fd6b5309f81de5a276f12855?s=96&d=mm&r=g\",\"contentUrl\":\"https:\\\/\\\/secure.gravatar.com\\\/avatar\\\/86630e27f5deecc5c393ea57fc7c3b6a068949f4fd6b5309f81de5a276f12855?s=96&d=mm&r=g\",\"caption\":\"Jonathan Kehayias\"},\"sameAs\":[\"http:\\\/\\\/3.209.169.194\\\/blogs\\\/jonathan\"]}]}<\/script>\n<!-- \/ Yoast SEO plugin. -->","yoast_head_json":{"title":"Incorrect Timestamp on Events in Extended Events - Jonathan Kehayias","robots":{"index":"index","follow":"follow","max-snippet":"max-snippet:-1","max-image-preview":"max-image-preview:large","max-video-preview":"max-video-preview:-1"},"canonical":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/","og_locale":"en_US","og_type":"article","og_title":"Incorrect Timestamp on Events in Extended Events - Jonathan Kehayias","og_description":"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\u2019ve seen this a couple of times on the MSDN Forums, and its come up a couple of times in discussions with other MVP\u2019s about Extended Events.  According to a feedback […]","og_url":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/","og_site_name":"Jonathan Kehayias","article_published_time":"2011-03-21T11:50:19+00:00","article_modified_time":"2017-04-13T16:12:25+00:00","author":"Jonathan Kehayias","twitter_misc":{"Written by":"Jonathan Kehayias","Est. reading time":"5 minutes"},"schema":{"@context":"https:\/\/schema.org","@graph":[{"@type":"Article","@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/#article","isPartOf":{"@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/"},"author":{"name":"Jonathan Kehayias","@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/#\/schema\/person\/01c10d94f3648654ef706d5e6305f69c"},"headline":"Incorrect Timestamp on Events in Extended Events","datePublished":"2011-03-21T11:50:19+00:00","dateModified":"2017-04-13T16:12:25+00:00","mainEntityOfPage":{"@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/"},"wordCount":1081,"commentCount":13,"articleSection":["Extended Events","SQL Server 2008"],"inLanguage":"en-US","potentialAction":[{"@type":"CommentAction","name":"Comment","target":["https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/#respond"]}]},{"@type":"WebPage","@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/","url":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/","name":"Incorrect Timestamp on Events in Extended Events - Jonathan Kehayias","isPartOf":{"@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/#website"},"datePublished":"2011-03-21T11:50:19+00:00","dateModified":"2017-04-13T16:12:25+00:00","author":{"@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/#\/schema\/person\/01c10d94f3648654ef706d5e6305f69c"},"breadcrumb":{"@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/#breadcrumb"},"inLanguage":"en-US","potentialAction":[{"@type":"ReadAction","target":["https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/incorrect-timestamp-on-events-in-extended-events\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Home","item":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/"},{"@type":"ListItem","position":2,"name":"Extended Events","item":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/category\/extended-events\/"},{"@type":"ListItem","position":3,"name":"Incorrect Timestamp on Events in Extended Events"}]},{"@type":"WebSite","@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/#website","url":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/","name":"Jonathan Kehayias - The Rambling DBA","description":"The Rambling DBA","potentialAction":[{"@type":"SearchAction","target":{"@type":"EntryPoint","urlTemplate":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/?s={search_term_string}"},"query-input":{"@type":"PropertyValueSpecification","valueRequired":true,"valueName":"search_term_string"}}],"inLanguage":"en-US"},{"@type":"Person","@id":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/#\/schema\/person\/01c10d94f3648654ef706d5e6305f69c","name":"Jonathan Kehayias","image":{"@type":"ImageObject","inLanguage":"en-US","@id":"https:\/\/secure.gravatar.com\/avatar\/86630e27f5deecc5c393ea57fc7c3b6a068949f4fd6b5309f81de5a276f12855?s=96&d=mm&r=g","url":"https:\/\/secure.gravatar.com\/avatar\/86630e27f5deecc5c393ea57fc7c3b6a068949f4fd6b5309f81de5a276f12855?s=96&d=mm&r=g","contentUrl":"https:\/\/secure.gravatar.com\/avatar\/86630e27f5deecc5c393ea57fc7c3b6a068949f4fd6b5309f81de5a276f12855?s=96&d=mm&r=g","caption":"Jonathan Kehayias"},"sameAs":["http:\/\/3.209.169.194\/blogs\/jonathan"]}]}},"_links":{"self":[{"href":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/wp-json\/wp\/v2\/posts\/530","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/wp-json\/wp\/v2\/users\/4"}],"replies":[{"embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/wp-json\/wp\/v2\/comments?post=530"}],"version-history":[{"count":0,"href":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/wp-json\/wp\/v2\/posts\/530\/revisions"}],"wp:attachment":[{"href":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/wp-json\/wp\/v2\/media?parent=530"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/wp-json\/wp\/v2\/categories?post=530"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/wp-json\/wp\/v2\/tags?post=530"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}