SQL Server: Correlating Timestamps From Various Data Points
Published Jan 15 2019 02:44 PM 491 Views
First published on MSDN on Sep 11, 2012

I was looking at data from a customer, in a different time zone (UTC+1) from mine, this week involving SQL Server AlwaysOn (HADRON) and found that lining up the timestamps in the various logs was challenging.   Some times are local to the SQL Server instance, others UTC and yet other utilities attempt to adjust the UTC time using your current client settings.

I found it helpful to build a table for what each log captures to help me understand the flow of the issue.

For this table assume local time is UTC+1 and my client is UTC-6.

Log/Location Units Example
Cluster Log (Line Header) - Yellow Below UTC 05:34:56.019
Cluster Log (AlwaysOn Message Text with embedded time) - Green Below Local time from GetDate() of the SQL Server instance 06:34:56.019
XEL Timestamp Column UTC adjusted for your clients time zone.  In my case UTC-6 with Daylight Saving Time (DST) enabled 00:34:56.019
XEL Create Time AlwaysOn - Event Data Column Local time from GetDate() of the SQL Server instance 06:34:56.019
SQL Server Error Log Local time from GetDate() of the SQL Server instance 06:34:56.019
Windows Event Logs (Captured on system to TXT) Local time of the customer system 06:34:56.019
Performance Monitor Capture Windows 8 Client - UTC
Windows 2008 R2 Client - UTC
Captured Mini/Dump File Current client time zone setting 00:34:56.019
SQL Agent Log Local time of the customer system 06:34:56.019
SQL Profiler Event Display Local time from GetDate() of the SQL Server instance 06:34:56.019
sys.fn_xe_file_target_read_file Event data timestamp data is UTC 05:34:56.019
Reporting Services - Trace Log Local server time 06:34:56.019
Reporting Services - HTTP Log UTC 05:34:56.019
Reporting Services - Execution Log Local Server time 06:34:56.019
Analysis Services - Profile Trace Local Server Time 06:34:56.019
Analysis Services - Server Log Local Server Time 06:34:56.019
SharePoint ULS Log Local Server Time 06:34:56.019

Note: Based on SQL Server 2008 R2 and SQL Server 2012, Windows 2008 R2 and Windows 8

Example of the cluster log, AlwaysOn entry

000015ec.00002a64::2012/09/06-05:34:56.019 INFO  [RES] SQL Server Availability Group: [hadrag] SQL Server component 'query_processing' health state has been changed from 'warning' to 'clean' at 2012-09-06 06:34:56.017

Example setting with my client time zone set to the same time zone as the customers (UTC+1) and restarting SQL Server Management Studio (SSMS) to show matching timestamp adjustment. Without the client adjustment the XEL display shows me 00:34:56.019 for my UTC-6 client settings.

Example output when I open the dump file on my client using UTC-6 setting with DST enabled.

Debug session time: Thu Sep  6 00:34:56.019 2012 (UTC - 5:00)

Example Output of a SQL Error log entry and matching .TRC entry

2012-09-06 06:35:37.05 spid478     The client was unable to reuse a session with SPID 478, which had been reset for connection pooling. The failure ID is 29. This error may have been caused by an earlier operation failing. Check the error logs for failed operations immediately before this error message.

As you might imagine: I have filed several work items to consolidate the times across this matrix of data points to make it easier to troubleshoot issues.

Bob Dorr - Principal SQL Server Escalation Engineer
assisted by Adam Saxton for (RS, AS and SharePoint)

Version history
Last update:
‎Jan 15 2019 02:44 PM
Updated by: