I discovered that digging into tempdb’s transaction log using the undocumented
fn_dblog is a surprisingly useful technique for finding data to help battle tempdb contention. But it’s not easy. The transaction log is cryptic and sorting through the information can be difficult.
Like many many others, I’ve found it difficult to avoid or diagnose tempdb allocation contention issues. Typical advice includes
- Use multiple equally-sized data files for tempdb
- Use trace flag 1118 in order to allocated full extents instead of mixed extents
- Look at your applications and avoid using tempdb so much
It’s that last point that is so tricky. I need to find out what parts of my application are using tempdb but tempdb is used for so many different things. Robert Davis lists eighteen different ways that SQL Server uses tempdb in his whitepaper Demystifying tempdb Performance and Manageability. So in order to tackle tempdb allocation contention, there are two things I want to do. I want to (A) measure tempdb allocations and (B) dig into tempdb allocations.
The Trouble (a Quick Recap)
Remember, tempdb is a resource shared by everyone using the database server. When a process wants to use space in tempdb, it allocates pages. Part of that allocation involves calling dibs for those pages by updating the Page Free Space (PFS) page and the Global Allocation Map (GAM) page. But updating those pages involves taking a short-lived latch on them. So with enough activity, we can see latch contention on these pages. Other people have done a better job explaining that than I did just now. You can probably find many of those explanations by googling tempdb latch contention.
Measuring Tempdb Allocations
So if latches on tempdb pages are a limited resource, then it would be wonderful to measure how often latches are taken there. That way developers could experiment to determine exactly what activities use tempdb and to what extent. Right now, that can’t be measured. Maybe we’re spoiled. We have a wide variety of extended events and a rich set of dynamic management views that let us dig really deep into internals. But when it comes to measuring tempdb latches, there’s no suitable metric.
Here’s how Microsoft does comes close:
|Metric||Why It’s Not What I Want|
|Performance counter Database transactions/sec specifically the tempdb database.||This is a gauge metric and could be useful if every tempdb transaction allocated a small number of pages. But at least one kind of activity – tempdb spills – will allocate many pages in a single tempdb transaction and so that activity gets hidden.|
|sys.dm_db_task_space_usage and sys.dm_db_session_space_usage||These are useful when you want to categorize tempdb allocations. It’s a picture of what tempdb allocations exist for any given point in time. But when I look at tempdb allocations in flight, long-running transactions will be over-reported and short-running transactions tend to be missed. This makes it difficult to tell whether the data indicates typical tempdb allocations or whether it’s just showing long held allocations.|
|Performance counter Page latch waits in Wait Statistics, specifically Waits started per second.||This is an alarm metric and not specific to tempdb.|
|Performance counter category Latches (any counter).||Again, these are all alarm metrics and not specific to tempdb.|
|Peformance counter Pages Allocated/sec or Page Deallocations/sec in Access Methods||I really like this one. It’s not tempdb specific, but it’s a gauge metric and it’s getting close to what I want.|
|Performance counter Tempdb latches/sec with instances on GAM, SGAM and PFS||Oooh perfect. Too bad this performance counter is fictional. It doesn’t exist. I would love this metric if it existed because it would be a gauge metric that most directly corresponds to tempdb contention problems.|
Digging into Tempdb Allocations
I’ve tried a number of ways to dig into where tempdb allocations are happening with limited success:
- I found that polling the DMV sys.dm_os_waiting_tasks (an alarm metric) doesn’t always give me the sql text I want.
- There are new extended events called
sqlserver.mixed_extent_deallocationintroduced in SQL Server 2014, but these are focused on mixed extents (which I already avoid by enabling trace flag TF-1118).
But it turns out that tempdb’s transaction log is rich with information (even though a lot of it is cryptic).
Digging into Tempdb’s Transaction Log
The easiest way to look at tempdb’s transaction log is by using
use tempdb; select * from fn_dblog(null, null);
But it can be a heavy query. Here’s a light-weight query that gets the most recent 5 seconds of activity or 10000 rows whichever is less:
-- Collect tempdb log activity use tempdb; -- get the latest lsn for tempdb declare @xact_seqno binary(10); declare @xact_seqno_string varchar(50); exec sp_replincrementlsn @xact_seqno OUTPUT; set @xact_seqno_string = '0x' + CONVERT(varchar(50), @xact_seqno, 2); set @xact_seqno_string = stuff(@xact_seqno_string, 11, 0, ':') set @xact_seqno_string = stuff(@xact_seqno_string, 20, 0, ':'); -- wait for five seconds of activity: waitfor delay '00:00:05'; select top 10000 * from fn_dblog(@xact_seqno_string, null); go
This actually lets me answer a lot of questions:
What activity is there against PFS or GAM pages?
Each operation (allocation or deallocation) is likely one page latch. So we have:
select * from fn_dblog(@xact_seqno_string, null) where Context in ('LCX_PFS', 'LCX_GAM', 'LCX_SGAM')
or aggregated we have:
select count(*), Context from fn_dblog(@xact_seqno_string, null) where Context in ('LCX_PFS', 'LCX_GAM', 'LCX_SGAM') group by Context order by count(*) desc;
What kinds of tempdb transactions are there?
select count(*), [Transaction Name] fn_dblog(@xact_seqno_string, null) where Operation = 'LOP_BEGIN_XACT' group by [Transaction Name] order by count(*) desc;
Transaction names are cryptic, but they are organized by activity and we can use some educated guesses to figure out what’s going on. For example, queries that use table valued parameters are called
TVQuery and are often associated with transactions called
FCheckAndCleanupCachedTempTable and if the TVP’s table type has a primary key defined, then
offline index build.
PFS or GAM activity by tempdb transaction type
Putting it all together:
with recentTempdbLogs as ( select top 10000 * from fn_dblog(@xact_seqno_string, null) ), TransactionNames as ( select [Transaction Id], [Transaction Name] from recentTempdbLogs where Operation = 'LOP_BEGIN_XACT' ) select tn.[Transaction Name], rtl.Context, COUNT(*) as Operations from recentTempdbLogs rtl join TransactionNames tn on tn.[Transaction Id] = rtl.[Transaction ID] where Context in ('LCX_PFS', 'LCX_GAM', 'LCX_SGAM') group by tn.[Transaction Name], Context order by COUNT(*) desc
How Is This Actionable?
Remus Rusanu has a post titled How to read and interpret the SQL Server log. It gives an introduction to some of the internals involved with what you see in the transaction log. It’s not always obvious why understanding SQL Server internals helps in real world scenarios. I’ve found that it’s most useful for troubleshooting by focusing avenues of investigation (whether it’s TVPs, tempdb spills, version store stuff, etc…).
In my case, I used this data to narrow down the type of activity. Specifically I used
- the Transaction SID column (giving me the user),
- the SPID which gives me the session id and helps me tie it to data collected elsewhere
- the AllocUnitName which I used to tie to a particular tempdb objects
More on what I found next week.