SQL Server bug: Incorrect values in sys.dm_db_session_space_usage for deferred drops

For the past few months I have been chasing down an issue which has been plaguing my attempts at tempdb monitoring, and in just the last week I’ve received news that it is indeed a confirmed bug in SQL Server.  I’m sharing what I’ve found here for the benefit of the SQL community.

One of the features I worked on for SQL diagnostic manager was our tempdb monitoring feature, whereby users can track and alert on a number of tempdb-specific metrics.  Among the items collected are the tempdb page allocation and deallocation values from sys.dm_db_session_space_usage and sys.dm_db_task_space_usage – specifically, the following columns:

  • user_objects_alloc_page_count
  • user_objects_dealloc_page_count
  • internal_objects_alloc_page_count
  • internal_objects_dealloc_page_count

The details of how to use these values in troubleshooting are covered in this Troubleshooting Insufficient Disk Space in tempdb article by Microsoft.  In brief, these values are intended to track the number of pages allocated or deallocated by a task or session, which can allow the practitioner to identify sessions which are using excessive amounts of space in tempdb or which are churning through a large number of pages over their lifetime.

We were periodically seeing cases where the apparent space used by a session – as calculated by subtracting the deallocation count from the allocation count for a session – was well in excess of the total size of tempdb.  I worked closely with Robert Davis (b|t) to identify whether this was a bug in the product or a misunderstanding of the contents of the DMV, but he confirmed our logic and believed it was probably a bug.  In deeper testing I was able to reproduce the issue very consistently using simple batches.  I’d like to walk you through the process.

In this example, a temp table is being created and then rows are being added.  I’ve noted the line where a “go 10″ is used – this causes the script to fill the temp table with 10 rows before dropping it. The script waits 10 seconds, then checks the allocation and deallocation counts from sys.dm_db_session_space_usage and sys.dm_db_task_space_usage.


set nocount on

create table #BigTempTable(a nchar(4000) default 'a')
go

insert into #BigTempTable default values

-- Note this value
go 10

drop table #BigTempTable

go

waitfor delay '00:00:10'

select
      'Session Space',
      ssu.session_id,
      sessionUserPagesAlloc = sum(ssu.user_objects_alloc_page_count),
      sessionUserPagesDealloc = sum(ssu.user_objects_dealloc_page_count),
      taskUserPagesAlloc = sum(tsu.user_objects_alloc_page_count),
      taskUserPagesDealloc = sum(tsu.user_objects_dealloc_page_count),
      sessionInternalPagesAlloc = sum(ssu.internal_objects_alloc_page_count),
      sessionInternalPagesDealloc = sum(ssu.internal_objects_dealloc_page_count),
      taskInternalPagesAlloc = sum(tsu.internal_objects_alloc_page_count),
      taskInternalPagesDealloc = sum(tsu.internal_objects_dealloc_page_count)
from
      tempdb.sys.dm_db_session_space_usage ssu
      left join tempdb.sys.dm_db_task_space_usage tsu
      on ssu.session_id = tsu.session_id
where
	ssu.session_id = @@spid
group by
      ssu.session_id

When run as above, with go 10, the DMV data returns exactly what is expected (I have switched rows and columns below for easy readability).

session_id 52
sessionUserPagesAlloc 16
sessionUserPagesDealloc 16
taskUserPagesAlloc 0
taskUserPagesDealloc 0
sessionInternalPagesAlloc 0
sessionInternalPagesDealloc 0
taskInternalPagesAlloc 0
taskInternalPagesDealloc 0

Each of the 10 loops adds 1 row to the temp table, and at that row size each row is 1 page.  The first 8 pages come from mixed extents, and pages 9 and 10 come from a second extent, for a total of 16 pages allocated to the table.  Upon dropping the table, all of that space is deallocated, so we see both an allocation and a deallocation of 16 pages.

If I reset the connection so I have a fresh spid and change the “go 10″ to “go 5000,” however, the returned data begins looking a bit suspect.

session_id 68
sessionUserPagesAlloc 5000
sessionUserPagesDealloc 0
taskUserPagesAlloc 0
taskUserPagesDealloc 0
sessionInternalPagesAlloc 0
sessionInternalPagesDealloc 0
taskInternalPagesAlloc 0
taskInternalPagesDealloc 0

At 5000 rows, this data divides up nicely into 625 extents, so exactly 5000 pages are allocated.  However, no pages are marked as deallocated even though the object was dropped.

If I remove the “where ssu.session_id = @@spid” clause and look at the space utilization of all sessions, I find that the deallocation value is apparently being credited to a system spid – in this case, spid 26:

This image shows that deallocations from spid 68 are apparently being tracked on system spid 26

So this is the cause of the incorrect values for session space used.  These two contrived examples show a small and a large temp table, and show that at a certain point the deallocated pages are being credited to a system spid.  In practice, however, workloads have a mix of small and large temporary objects, so the deallocation value is often non-zero but still incorrect.

When we first observed this problem Robert mentioned that he thought it was probably an issue to do with deferred drops in tempdb.  In the last week I’ve heard back from Microsoft, who have confirmed this.  Specifically, the problem is that deferred drops of over 128 extents are not incrementing the user_objects_dealloc_page_count in sys.dm_db_session_space_usage.  Hop on over to this post on Robert’s blog, where he describes this issue and the concept of deferred drops in great detail.

Just wanted to share these findings with the community.  To my reading, these DMVs remain useful to give overall impressions of how much space is being used by sessions and can be used to identify the sessions which are using tempdb most heavily over time.  While this bug is in place, however, it is not possible to state that subtracting deallocations from allocations will yield current usage for a specific session.

Many thanks to the folks at SQLClinic at PASS Summit, to the CSS escalation team at Microsoft, and to Robert Davis for helping identify this issue.  Don’t miss Robert’s post, which has some important details about how deferred drops work.

May 21, 2013 Posted by: 4 Comments - Permalink
4 Responses to SQL Server bug: Incorrect values in sys.dm_db_session_space_usage for deferred drops
  1. Hi Vicky,

    many thank’s for this useful information ! I was looking for an explanation regarding the issue you describe,
    But I have another problem. Very often, I obtain more deallocated page than allocated page for a particular session (system session and / or user session), even if I sum the value with the sys.dm_db_session_task_usage. That sound’s a bit strange to me. Do you have any idea about this ?
    With such values, I obtain negative amount of space when I look for space used in tempDB by session.

    Thank’s a lot

    O.

    • Vicky says:

      Hello Olivier,

      I think this could be the natural inverse to the symptom I was researching. In my example screenshot above, session 26 shows deallocations with no allocations credited, which sounds like what you are seeing.

      Does that make sense? If you sum all the deallocations and allocations across all sessions are you able to get them to zero out?

  2. Hello Vicky,

    I would like first to thank you for taking time to give me a such quick answer.
    Your explanation make sense to me, but won’t be enough in some situation. Let me explain.
    I’m currently collecting the sys.dm_db_task_space_usage DMV into a dedicated table.
    Now, if I query this table, I observe that I have a lot of session with only a few page allocated (often 16 or 24 pages), and more pages deallocated (the difference is often 8 more pages deallocated than allocated in my test environnment).
    I think the deferred drop explanation can take place here as it concern very small volume of data.
    Here is a result I have when I query my Table :
    select DateCollect
    , session_id,internal_objects_alloc_page_count
    , internal_objects_dealloc_page_count,
    user_objects_alloc_page_count
    , user_objects_dealloc_page_count
    from DMV_dm_db_task_space_usage
    where session_id=59
    order by DateCollect, session_id

    DateCollect session_id internal_objects_alloc_page_count internal_objects_dealloc_page_count
    2013-05-30 05:45:00.710 59 16 24
    2013-05-30 06:00:01.013 59 0 0
    2013-05-30 06:15:00.287 59 0 0
    2013-05-30 06:30:00.520 59 0 0
    2013-05-30 06:45:00.873 59 0 0
    2013-05-30 07:00:00.143 59 16 24
    2013-05-30 07:15:00.467 59 16 24
    2013-05-30 07:30:00.750 59 0 0
    2013-05-30 07:45:01.063 59 24 32
    2013-05-30 08:00:00.407 59 0 0
    2013-05-30 08:30:01.033 59 16 24
    2013-05-30 09:00:00.600 59 0 0

    I’m running on a sql server 2008 SP3. I can send you by mail the script I use if you want to build a similar test.

    thank you

    O.

    • Vicky says:

      Are you also taking into consideration the values in sys.dm_db_session_space_usage? Consider this script:

      create table #temp(c char(100))

      go

      insert into #temp default values

      go 100

      delete from #temp

      waitfor delay ’00:05:00′

      In my environment I ran this on spid 59, and then in another session, I ran this:

      select
      ‘Session Space’,
      ssu.session_id,
      sessionUserPagesAlloc = sum(ssu.user_objects_alloc_page_count),
      sessionUserPagesDealloc = sum(ssu.user_objects_dealloc_page_count),
      taskUserPagesAlloc = sum(tsu.user_objects_alloc_page_count),
      taskUserPagesDealloc = sum(tsu.user_objects_dealloc_page_count),
      sessionInternalPagesAlloc = sum(ssu.internal_objects_alloc_page_count),
      sessionInternalPagesDealloc = sum(ssu.internal_objects_dealloc_page_count),
      taskInternalPagesAlloc = sum(tsu.internal_objects_alloc_page_count),
      taskInternalPagesDealloc = sum(tsu.internal_objects_dealloc_page_count)
      from
      tempdb.sys.dm_db_session_space_usage ssu
      left join tempdb.sys.dm_db_task_space_usage tsu
      on ssu.session_id = tsu.session_id
      where
      ssu.session_id = 59
      group by
      ssu.session_id

      The results show 2 allocated pages for the session, and 2 deallocated pages for the task. Taken only from the perspective of the session or the task the picture would not be complete. This could be an oversimplification but if you are only looking at the sys.dm_db_task_space_usage DMV you are not getting the entire picture.

Leave a Reply

%d bloggers like this: