SQL Server: Correlating Timestamps From Various Data Points
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 |
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)