How It Works: SQL Server Timings and Timer Output (GetTickCount, timeGetTime, QueryPerformanceCounter, RDTSC, …)

[mssql-support]

First published on MSDN on May 29, 2009

A series of questions related to start time, duration, end time, T-SQL waitfor delay command and others crossed my path again this week.    As I was trying to explain it to a fellow engineer and I realized it has become a bit complicated.

The problem stems from a lack of a reliable, light-weight, high resolution timer that does not require additional CPU cycles leading to unwanted power consumption.   For example, on a laptop running SQL Express you are often more concerned about battery life than you are high resolution timing of trace events and query execution.

Across the broad spectrum of hardware there are a couple of timer choices.  Several timers of differing accuracy are offered by the operating system: http://support.microsoft.com/kb/172338 and Microsoft is currently working with hardware manufactures to accommodate a lightweight, high resolution timer.

Function                 Units                      Resolution
---------------------------------------------------------------------------
Now, Time, Timer         seconds                    1 second
GetTickCount             milliseconds               approx. 10 ms
TimeGetTime              milliseconds               approx. 10 ms
QueryPerformanceCounter  QueryPerformanceFrequency  same

Interrupt Ticks

Interrupt ticks are accurate but not high resolution – I.E. GetTickCount.   The common interrupt clock activity yields ~12ms granularity but can vary based on hardware and the BIOS.    This is the central timer mechanism used by Windows.

For example, SQL Server uses this as the basis for all DATETIME, DATE, TIME, DATETIME2, … and other time based types and calculations.   It also uses it for all timeout and delay calculations.   This would include but not be limited to query timeout, lock timeout, and T-SQL waitfor delay command.

RDTSC Ticks

The RDTSC ticks are the raw CPU ticks.   The CPU ticks are incremented by the CPU at the frequency the CPU is running.   This can vary as CPU frequencies are altered to save power.    It is difficult to use this raw counter as a basis for timing when the CPU frequencies are altered but various implementations are available.

QueryPerformanceCounter ( http://msdn.microsoft.com/en-us/library/ms644904.aspx )

The QPC is a high resolution counter that attempts to determine the best high resolution counter available to it.  It attempts to tick an exposed counter at a constant frequency so external applications can use the counter for high resolution timings.   However, to keep the counter a constant frequency can be an involved process and not always accurate.

On some hardware the boot.ini must contain the /USEPMTIMER ( http://support.microsoft.com/kb/895980 ) switch to improve the QPC accuracy by forcing use of the ACPI clock instead of the TSC.   This is usually reported by customers as strange performance counter behaviors.

http://blogs.technet.com/perfguru/archive/2008/02/18/explanation-for-the-usepmtimer-switch-in-t...

SQL and Timers

Now that I have recapped the basic timers I will attempt to explain the different uses of the timers by SQL Server.

SQL 2000	Trace events used the interrupt timer producing ~12ms granularity for trace events and other timing outputs. This was accurate but the granularity made it hard to track down issues for queries that took less than ~12ms.    If a query ran in 4ms it would commonly show a duration of 0 because the start and end tick count was the same.    If the query executed 1 million times a day it could be your largest CPU consumer but difficult to determine. Support also struggled with this because if the query was running at 4ms but something changed, making it execute in 8ms it was still reported with 0 millisecond duration.  Support and the DBA could tell a specific set of queries are taking twice as long but it was difficult to pinpoint the source of the problem. Other timing outputs such as statistics time used the RDTSC counter.   This is prone to errors because of the CPU frequency changes.
SQL 2005 until SP3	Trace events and other use the RDTSC timer to achieve high resolution timings.   This is prone to errors because of the CPU frequency changes but SQL Server attempted to accommodate this when possible or warn the user about frequency drift in the SQL Server error log.
SQL 2005 SP3	Ported some of the SQL 2008 changes into the SQL 2005 SP3 release. Instead of the RDTSC timer and adjusted interrupt timer is used.  The API timeBeginPeriod ( http://msdn.microsoft.com/en-us/library/ms713413.aspx ) can be called to lower the granularity from ~12ms to 1ms.    During startup SQL Server attempts to lower the granularity to 1ms. The outputs allow much better troubleshooting granularity at 1ms but the system may consume additional power.
SQL 2008	Trace events and some XEvents use QueryPerformanceCounter, returning microsecond timing to these outputs.   This is a heavier timer and can require the boot.ini switch of /USEPMTIMER to retain accuracy. Most of the other timing outputs use the adjusted interrupt timer (timeBeginPeriod) as discussed in the SQL Server 2005 SP3 section above.

Power Management Incompatability - timeBeginPeriod

We have seen a couple of issues with BIOS bugs where setting the interrupt timer frequency to 1ms results in operating system warnings.

Event Source:    W32Time  Event ID:              50

The time service detected a time difference of greater than 5000 milliseconds  for 900 seconds. The time difference might be caused by synchronization with  low-accuracy time sources or by suboptimal network conditions. The time service is no longer synchronized and cannot provide the time to other clients or update  the system clock. When a valid time stamp is received from a time service  provider, the time service will correct itself.

The workaround for this is to start SQL Server with trace flag –T8038.   The trace flag disables the call to timeBeginPeriod retaining the default interrupt timing granularity ~12ms.    The SQL Server timings return to the lower granularity setting but power consumption is reduced and the BIOS bug avoided.

Power Consumption

On laptops battery life is a priority.  When running SQL Server builds SQL Server 2005 SP3, SQL 2008 and newer adding the trace flag –T8038 to avoid the timeBeginPeriod call retains the lower granularity setting and power consumption is reduced.   Be aware that use of the trace flag reduces accuracy of the SQL Server trace events and other SQL Server timing outputs.

Duration and End Time Invalid

Customer reported that the duration and end time for a trace event on SQL Server 2008 was invalid.   It was showing ~5min of duration but the query timeout was 30 seconds.   Looking at this closer the QueryPerformanceCounter (QPC) was not accurate and required the boot.ini switch /USEPMTIMER.

Idle SQL Server

The SQL Server Express SKU is designed to go into an idle state.   Around 15 minutes if SQL Server has detected no query activity it will suspend all internal tasks (Checkpoint, Lazy writer, Lock Monitor, ….) to reduce CPU consumption.   It is woken when a new request arrives or Windows indicates a significant memory change event  When the SQL Server is declared idle it returns the interrupt timer (multi-media timer) to the original default to reduce power consumption.   When SQL Server is woken it will return to the 1ms timing granularity unless trace flag –T8038 is enabled.

Note: Microsoft is currently evaluating the need to make –T8038 on by default for the SQL Express variety of SKUs.

Additional References