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:
- sys.dm_os_wait_stats
- sys.dm_os_waiting_tasks
- sys.dm_os_latch_stats
- sys.dm_os_spinlock_stats (this one isn’t documented at all and is only mentioned in a few places online)
A few weeks ago I kicked off a survey to find out whether you’ve heard of or used these DMVs. 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).
sys.dm_os_wait_stats
Other values:
- 12 x Yes, more than once or twice but not routinely.
- 2 x Only because of your wait statistics post.
The survey results are not surprising, especially among 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.
sys.dm_os_waiting_tasks
Other values:
- 6 x Yes, More than once or twice but not routinely.
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 create 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):
1
2
| 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.)
My colleague Joe Sack 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 (note that ‘text’ on one line does not have delimiters because that messes up the code formatting pluging):
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
| SELECT [owt].[session_id], [owt].[exec_context_id], [owt].[wait_duration_ms], [owt].[wait_type], [owt].[blocking_session_id], [owt].[resource_description], CASE [owt].[wait_type] WHEN N 'CXPACKET' THEN RIGHT ([owt].[resource_description], CHARINDEX (N '=' , REVERSE ([owt].[resource_description])) - 1) ELSE NULL END AS [Node ID], [es].[program_name], [est].text, [er].[database_id], [eqp].[query_plan], [er].[cpu_time] 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 ORDER BY [owt].[session_id], [owt].[exec_context_id]; 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 ofDROP TABLE and SELECT * INTO of global temp tables) and the XML query plans. Clicking on one of them in 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_tasksDMV to see which queries are waiting for those resources – and then dive in deeper to see why.
sys.dm_os_latch_stats
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 synchronization 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:
1
2
| DBCC SQLPERF( 'sys.dm_os_latch_stats' , CLEAR); GO |
An example set of output from the DMV is:
1
2
3
4
| 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:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
| 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 ( N 'BUFFER' ) --AND [wait_time_ms] > 0 ) 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.
sys.dm_os_spinlock_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:
1
2
3
| 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:
1
2
3
4
5
6
7
8
9
10
11
12
13
| IF OBJECT_ID (N '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.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
| IF EXISTS ( SELECT * FROM [tempdb].[sys].[objects] WHERE [ name ] = N '##TempSpinlockStats1' ) DROP TABLE [##TempSpinlockStats1]; IF EXISTS ( SELECT * FROM [tempdb].[sys].[objects] WHERE [ name ] = N '##TempSpinlockStats2' ) DROP TABLE [##TempSpinlockStats2]; GO -- Baseline SELECT * INTO [##TempSpinlockStats1] FROM sys.dm_os_spinlock_stats WHERE [collisions] > 0 ORDER BY [ name ]; GO -- Now do something DBCC CHECKDB (N 'SalesDB' ) WITH NO_INFOMSGS; GO -- Capture updated stats 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]) / ([ts2].[collisions] - [ts1].[collisions]) END AS [SpinsPerCollision], [ts2].[sleep_time] - [ts1].[sleep_time] AS [DiffSleepTime], [ts2].[backoffs] - [ts1].[backoffs] AS [DiffBackoffs] 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.