It's all very well having whizz-bang 3rd-party performance monitoring and troubleshooting tools, but sometimes you have to get deeper into what's going on with SQL Server than any of these tools can go. Or you have to call Customer Support or Premier Support so *they* can dive in deeper.
Typically you or they are going to make use of four DMVs that give increasingly advanced information about what's going on for use in performance troubleshooting:
A few weeks ago I kicked off a survey to find out whether you've heard of or used these DMVs - see here for the survey.
In this post I'm going to present the survey results and explain a bit about these DMVs, focusing the most attention on latches and spinlocks. This started out as a small post but grew into a 10-page, 2500 word article :-)
Here are the results (in each of the Other values, a few people asked what DMVs are - see Dynamic Management Views and Functions in BOL):
Other values:
The survey results are not surprising, especially amongst readers of my blog.
Wait statistics are the bread-and-butter of performance tuning. SQL Server is keeping track of what resources threads need to wait for, and how long they need to wait. By analyzing which resources (and combinations of resource) are being waited for the most, you can get an idea of where to start digging in further. An example might be that if most of the waits are PAGEIOLATCH_SH waits, and this wasn't the case in your wait stats baseline, you might look at the I/O subsystem performance using the sys.dm_io_virtual_file_stats DMV (which I blogged about here).
Last December I wrote a long blog post introducing wait statistics, showing how to use the sys.dm_os_wait_stats DMV, giving links to resources, and explaining the most common ones that people see in the field based on data from more than 1800 SQL Servers - see Wait statistics, or please tell me where it hurts.
Other values:
I'm surprised that these results don't tie in more closely with the results for sys.dm_os_wait_stats, but they're reasonably close.
The sys.dm_os_waiting_tasks DMV shows you what is currently being waited on by everything running on the system.
I created a scenario with 200 clients creating and dropping small temp tables to creat tempdb latch contention. Using the DMV, I can see what's being waited on (I've removed the columns describing blocking from the output in this case to make it fit on screen)
SELECT * FROM sys.dm_os_waiting_tasks;
GO
waiting_task_address session_id exec_context_id wait_duration_ms wait_type resource_address resource_description
-------------------- ---------- --------------- -------------------- ------------------ ------------------ --------------------
0x000000000044E508 2 0 4091305 XE_DISPATCHER_WAIT NULL NULL
0x000000000044E988 9 0 4121252 FSAGENT NULL NULL
0x000000000044EBC8 20 0 4121251 BROKER_TRANSMITTER NULL NULL
0x000000000044F4C8 63 0 53 PAGELATCH_EX 0x0000000088FFEED8 2:1:1139
0x000000000044EE08 64 0 8 PAGELATCH_UP 0x0000000080FE8AD8 2:1:1
0x000000000044F288 87 0 0 PAGELATCH_UP 0x0000000080FE8AD8 2:1:1
0x000000000044F048 91 0 53 PAGELATCH_EX 0x0000000088FFEED8 2:1:1139
0x000000000044F948 92 0 61 PAGELATCH_EX 0x0000000088FFEED8 2:1:1139
0x000000000044F708 101 0 10 PAGELATCH_EX 0x0000000080FEEC58 2:1:120
0x000000000044FDC8 103 0 37 PAGELATCH_UP 0x0000000080FE8AD8 2:1:1
0x000000008744E088 118 0 11 PAGELATCH_EX 0x0000000080FEEC58 2:1:120
0x000000008744E2C8 121 0 66 PAGELATCH_UP 0x0000000080FE8AD8 2:1:1
0x000000008744E508 122 0 33 PAGELATCH_EX 0x0000000080FEEC58 2:1:120
0x000000008744E748 155 0 32 PAGELATCH_EX 0x0000000080FEEC58 2:1:120
0x000000008744E988 158 0 27 PAGELATCH_EX 0x0000000080FEEC58 2:1:120
0x000000008744EBC8 163 0 34 PAGELATCH_EX 0x0000000080FEEC58 2:1:120
0x000000008744EE08 168 0 66 PAGELATCH_UP 0x0000000080FE8AD8 2:1:1
0x000000008744F048 179 0 26 PAGELATCH_UP 0x0000000080FE8AD8 2:1:1
.
.
As you can see, the classic tempdb latch contention is showing - page ID (2:1:1) - the first PFS page in tempdb. (See here for more on tempdb contention, and here for more on PFS pages.)
Joe Sack (blog|twitter) created a script that pulls in data from a bunch of other DMVs to make the sys.dm_os_waiting_tasks output more useful, which I've modified into the following:
SELECT
owt.session_id,
owt.wait_duration_ms,
owt.wait_type,
owt.blocking_session_id,
owt.resource_description,
es.program_name,
est.text,
est.dbid,
eqp.query_plan,
es.cpu_time,
es.memory_usage
FROM sys.dm_os_waiting_tasks owt
INNER JOIN sys.dm_exec_sessions es
ON owt.session_id = es.session_id
INNER JOIN sys.dm_exec_requests er
ON es.session_id = er.session_id
OUTER APPLY sys.dm_exec_sql_text (er.sql_handle) est
OUTER APPLY sys.dm_exec_query_plan (er.plan_handle) eqp
WHERE es.is_user_process = 1;
GO
There's too much information in the output to usefully show in this post, but I can see the actual T-SQL statements being run (in this case a lot of DROP TABLE and SELECT * INTO of global temp tables) and the XML query plans. Clicking on one of them in 2008 SSMS gives me the actual plan - very cool:
This means I can see from the sys.dm_os_wait_stats DMV what the prevalent resource waits are, then use the sys.dm_os_waiting_tasks DMV to see which queries are waiting for those resources - and then dive in deeper to see why.
As I suspected most readers have heard of latches, but 75% of respondents haven't used the DMV or have only used it once or twice.
A latch is a lightweight syncronization mechanism that protects access to read and change in-memory structures - for instance, 8KB page buffers in the buffer pool (latch type = BUFFER), or the data structure that represents a database's data and log files (latch type = FGCB_ADD_REMOVE). A latch is only held for the duration of the operation, unlike a lock which may be held until a transaction commits. One example of locks and latches - imagine a table where an update query has caused lock escalation so that a table X lock is held on the table. As the query continues updating more records in the table, it won't acquire any more locks, but any data and index pages that are updated in memory must be EX (exclusive) latched before the update can occur. The latch acts as the synchronization mechanism to prevent two threads updating the page at the same time, or a thread reading the page while another is in the middle of updating it. Another example is if you run a select query using NOLOCK - although the query will not acquire SH (share) locks at any level in the table, the threads must acquire SH latches on pages before they can be read - to synchronize with possible concurrent updaters.
If a thread requires a latch it will be moved from RUNNING to SUSPENDED and put on the waiter list to await notification that the latch has been acquired in the requested mode.
Latch waits correspond to LATCH_XX waits in the output from the sys.dm_os_wait_stats DMV, so digging into to which latches are accounting for most waits can show where a bottleneck is on the system.
You can reset latch wait statistics just like regular wait statistics using:
DBCC SQLPERF('sys.dm_os_latch_stats', CLEAR);
GO
An example set of output from the DMV is:
SELECT * FROM sys.dm_os_latch_stats
WHERE [waiting_requests_count] > 0
ORDER BY [wait_time_ms] DESC;
GO
latch_class waiting_requests_count wait_time_ms max_wait_time_ms
--------------------------------- ---------------------- -------------------- --------------------
BUFFER 113181121 466697044 1233
ACCESS_METHODS_HOBT_COUNT 66676 331193 577
ACCESS_METHODS_HOBT_VIRTUAL_ROOT 15018 68865 125
LOG_MANAGER 130 5610 234
FGCB_ADD_REMOVE 299 5073 32
TRACE_CONTROLLER 1 0 0
VERSIONING_TRANSACTION_LIST 1 0 0
ACCESS_METHODS_HOBT_FACTORY 64 0 0
You can also aggregate them in the same way as I described in my big wait stats blog post, using code below:
WITH Latches AS
(SELECT
latch_class,
wait_time_ms / 1000.0 AS WaitS,
waiting_requests_count AS WaitCount,
100.0 * wait_time_ms / SUM (wait_time_ms) OVER() AS Percentage,
ROW_NUMBER() OVER(ORDER BY wait_time_ms DESC) AS RowNum
FROM sys.dm_os_latch_stats
WHERE latch_class NOT IN ('BUFFER')
)
SELECT
W1.latch_class AS LatchClass,
CAST (W1.WaitS AS DECIMAL(14, 2)) AS Wait_S,
W1.WaitCount AS WaitCount,
CAST (W1.Percentage AS DECIMAL(14, 2)) AS Percentage,
CAST ((W1.WaitS / W1.WaitCount) AS DECIMAL (14, 4)) AS AvgWait_S
FROM Latches AS W1
INNER JOIN Latches AS W2
ON W2.RowNum <= W1.RowNum
GROUP BY W1.RowNum, W1.latch_class, W1.WaitS, W1.WaitCount, W1.Percentage
HAVING SUM (W2.Percentage) - W1.Percentage < 95; -- percentage threshold
GO
Here's an example after clearing the latch stats and running the tempdb contention test (I described above) for 30 seconds:
LatchClass Wait_S WaitCount Percentage AvgWait_S
--------------------------------- ------- ---------- ----------- ----------
ACCESS_METHODS_HOBT_COUNT 7.92 1471 75.41 0.0054
ACCESS_METHODS_HOBT_VIRTUAL_ROOT 1.38 393 13.15 0.0035
LOG_MANAGER 1.20 12 11.44 0.1001
Most of the latch classes are undocumented, but I'll be shedding light on them as I blog more about latch stats.
Other values:
-
1 x Just learned of this at SQLskills training!
-
1 x Learned about it, after you tweeted about it on 3/23 to a co-worker.
This is really cool that more than 40% of respondents have never heard of this DMV or spinlocks - education time!
A spinlock is another lightweight synchronization mechanism used to control access to certain data structures in the engine - used when the time that the spinlock will be held is very short. They are different from latches because a thread waiting for a latch will yield the scheduler and go onto the waiter list whereas a thread waiting to acquire a spinlock will burn some CPU "spinning" to see if it can get the CPU before giving up and backing off (yielding the scheduler) before trying again. This may allow another thread to execute that is holding the spinlock and eventually release it, allowing the system to proceed (yes, a thread can yield the scheduler and move to the waiter list while holding a spinlock!) because another thread can then acquire the spinlock.
It is perfectly normal for spinlock collisions and spins to occur on a busy system, but sometimes a bottleneck can occur on systems with larger numbers of CPUs where collisions are more likely - this can drain CPU resources while many threads are spinning trying to acquire the spinlock.
Running the DMV shows you the list of all spinlocks on the system (all of which are undocumented - but I'll be working on that going forward) - here is some partial output:
SELECT * FROM sys.dm_os_spinlock_stats
ORDER BY [spins] DESC;
GO
name collisions spins spins_per_collision sleep_time backoffs
------------------ -------------------- -------------------- ------------------- -------------------- -----------
LOCK_HASH 3629624 4402099957 1212.825 561 817819
SOS_CACHESTORE 11992297 3352117666 279.5226 6093 71948
OPT_IDX_MISS_KEY 63329610 2036811058 32.16207 15830 180845
SOS_TLIST 9769744 574740437 58.82861 320 3619
SOS_SCHEDULER 2137875 107392996 50.23352 557 7753
MUTEX 676406 83493780 123.4374 340 3300
LOGCACHE_ACCESS 2210697 83204315 37.63714 0 252366
SOS_RW 264489 70122059 265.1228 14 799
XDESMGR 346005 61031449 176.3889 216 3788
SOS_SUSPEND_QUEUE 3397384 53752545 15.82174 120 2384
OPT_IDX_STATS 129814 19800952 152.5332 27 356
BACKUP_CTX 29730 16784471 564.5635 192 1645
LOCK_RESOURCE_ID 17558 4363116 248.4973 20 375
SOS_TASK 206597 1898063 9.187273 16 171
XVB_LIST 266112 882691 3.316991 1 63
.
.
[
On 2005 you'll need to use DBCC SQLPERF ('spinlockstats') and use INSERT/EXEC to get the results into a table. Eric Humphrey (blog|twitter) put the code together:
-- Baseline
IF OBJECT_ID('tempdb..#TempSpinlockStats1') IS NOT NULL
DROP TABLE #TempSpinlockStats1;
GO
CREATE TABLE #TempSpinlockStats1(
[name] NVARCHAR(30) NOT NULL,
[collisions] BIGINT NOT NULL,
[spins] BIGINT NOT NULL,
[spins_per_collision] FLOAT NOT NULL,
[sleep_time] BIGINT NOT NULL,
[backoffs] BIGINT NOT NULL
)
INSERT INTO #TempSpinlockStats1
EXEC ('DBCC SQLPERF(''spinlockstats'')')
GO
]
The LOCK_HASH spinlock, for instance, is used by the lock manager to look at one of the hash buckets holding lock resource hashes to tell whether lock can be granted or not.
The sleep_time is an aggregate of how much time is spent sleeping between spin cycles when a backoff occurs.
I've put together some code that will allow you to see what spinlock activity occurs between two times. The code captures the output from the DMV into two temp tables, with whatever time period you want in between (to allow you to run a command), and then shows the difference between the two sets of data. I'll show an example of running DBCC CHECKDB.
-- Baseline
DROP TABLE ##TempSpinlockStats1;
GO
SELECT * INTO ##TempSpinlockStats1 FROM sys.dm_os_spinlock_stats
WHERE [collisions] > 0
ORDER BY [name];
GO
-- Do some stuff
DBCC CHECKDB (SalesDB) WITH NO_INFOMSGS;
GO
-- Capture updated stats
DROP TABLE ##TempSpinlockStats2;
GO
SELECT * INTO ##TempSpinlockStats2 FROM sys.dm_os_spinlock_stats
WHERE [collisions] > 0
ORDER BY [name];
GO
-- Diff them
SELECT
'***' AS [New],
ts2.[name] AS [Spinlock],
ts2.[collisions] AS [DiffCollisions],
ts2.[spins] AS [DiffSpins],
ts2.[spins_per_collision] AS [SpinsPerCollision],
ts2.[sleep_time] AS [DiffSleepTime],
ts2.[backoffs] AS [DiffBackoffs]
FROM ##TempSpinlockStats2 ts2
LEFT OUTER JOIN ##TempSpinlockStats1 ts1
ON ts2.[name] = ts1.[name]
WHERE ts1.[name] IS NULL
UNION
SELECT
'' AS [New],
ts2.[name] AS [Spinlock],
ts2.[collisions] - ts1.[collisions] AS [DiffCollisions],
ts2.[spins] - ts1.[spins] AS [DiffSpins],
CASE (ts2.[spins] - ts1.[spins]) WHEN 0 THEN 0
ELSE (ts2.[spins] - ts1.[spins]) / -- > 0 spins = > 0 collisions
(ts2.[collisions] - ts1.[collisions]) END AS [SpinsPerCollision],
ts2.[sleep_time] - ts1.[sleep_time] AS [DiffSleepTime],
ts2.[backoffs] - ts1.[backoffs] AS [DiffBackoffs]
--, ts2.*
FROM ##TempSpinlockStats2 ts2
LEFT OUTER JOIN ##TempSpinlockStats1 ts1
ON ts2.[name] = ts1.[name]
WHERE ts1.[name] IS NOT NULL
AND ts2.[collisions] - ts1.[collisions] > 0
ORDER BY [New] DESC, [Spinlock] ASC;
GO
And the output is as follows:
New Spinlock DiffCollisions DiffSpins SpinsPerCollision DiffSleepTime DiffBackoffs
---- ------------------ -------------------- -------------------- ----------------- -------------------- ------------
*** DBCC_CHECK 4 24 6 0 0
*** DIAG_MANAGER 1 0 0 0 0
*** FCB_REPLICA_SYNC 10 16147 1614.7 0 0
*** LSID 9 0 0 0 0
*** QUERYEXEC 5 0 0 0 0
*** X_PACKET_LIST 2 0 0 0 0
*** X_PORT 8 227 28.375 0 0
*** XACT_WORKSPACE 11 0 0 0 0
*** XID_ARRAY 7 0 0 0 0
BUF_FREE_LIST 2 0 0 0 0
HOBT_HASH 2 1 0 0 0
LOCK_HASH 3 1818 606 0 0
SOS_RW 2 500 250 0 0
SOS_SCHEDULER 5 6 1 0 0
SOS_SUSPEND_QUEUE 11 39 3 0 0
SOS_TASK 1 0 0 0 0
SOS_TLIST 1 0 0 0 0
You can see here which spinlocks were acquired to run the DBCC CHECKDB commands - those marked with *** did not appear in the 'before' set of spinlock stats. More on all of these in future posts.
You can also investigate spinlocks using extended events - again, more on that in future.
Summary
It's possible to dive really deeply into what's happening inside SQL Server using these four DMVs. Spinlocks in particular - what each means, what each controls and what contention on each them means (plus what you can do about it) - involve a lot of knowledge of what's going on inside the engine, and I'm planning to spread some of that knowledge going forward - there's an enormous amount of information to be published about latches and spinlocks.
Hope you'll join me to learn about these - let me know if you find this stuff interesting and useful.
Thanks!