Take the 2-minute tour ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.

Is anyone able to explain some behaviour I'm seeing with SQL Profiler? Taking the following two batches:

exec sp_executesql N'
    declare @t table (
        x int
    )

    insert into @t (x) select top 10 number from dbo.gennumbers

    select * from @t
    union
    select * from @t
'

exec sp_executesql N'
    select top 10 number from dbo.gennumbers
    union
    select top 10 number from dbo.gennumbers
'

(this is a simplification of some refactoring I'm doing; in reality the temp table is populated through a CTE that's reused in the final query, so mitigating the amount of duplicated work SQL Server needs to do by caching the data).

In this example, GenNumbers is simply a numbers table with a single column that just contains a sequential run of numbers - nothing special.

In profiler, I'm getting the follow results:

Batch 1, with the temp table:

Event             TextData            Reads
SP:StmtCompleted  INSERT INTO(...)    27
SP:StmtCompleted  SELECT * FROM ...   6
SQL:StmtCompleted exec sp_executesql  170

Batch 2, a direct hit:

Event             TextData              Reads
SP:StmtCompleted  SELECT TOP 10 * ...   6
SQL:StmtCompleted exec sp_executesql    6

What I'm trying to understand is the anomoly of the final read count on the SQL:StmtCompleted. I was expecting that the total reads should equal the sum of all reads that occur within the batch, however that doesn't seem to be the case in batch 1 - in fact, it's significantly higher. Whereas batch 2, that does a single select, final reads == actual reads.

There's nothing obvious in the execution plan to see where this extra time is going, but maybe I'm not capturing the right thing - does anyone have any thoughts on what's actually going on? I'm wondering whether I need to worry about the extra 100 reads that SQL Server is "giving" me, given that this read count is five or six times higher than the actual read count.

I'm assuming it's something to do with SQL needing to maintain information about the temporary table, but it's not clear exactly what. Any light shed would be useful.

share|improve this question

1 Answer 1

up vote 3 down vote accepted

There is an implicit CREATE TABLE at the beginning and DROP TABLE @T at the end as the table goes out of scope that aren't associated with either the INSERT or the SELECT statement.

If you replace with a #temp table you should see some additional reads for both the drop and create statements. For me I see 36 for the CREATE and 100 for the DROP so that accounts for 136 of your missing 137 reads.

(Script with #temp table)

EXEC sp_executesql N'
   CREATE TABLE #T 
  ( 
     x INT 
  ) 

INSERT INTO #T 
            (x) 
SELECT TOP 10 number 
FROM   master..spt_values 

SELECT * 
FROM   #T 
UNION 
SELECT * 
FROM   #T 

DROP TABLE #T
'
share|improve this answer
    
Yep - I see similar here, although the drop is 123 reads. It's sometimes the obvious things that get overlooked: thought I'd tried this once. Obviously not :-) I'm assuming there's no way to get profiler to include these implicit actions (more for future reference, than anything now). –  Chris J Apr 6 '12 at 12:39
1  
@ChrisJ - No I don't think so. The CREATE of a table variable happens implicitly when the script is executed (even if the path of execution never includes the actual DECLARE statement) and similarly for the drop. These internal commands aren't traceable through Profiler and so the only way of seeing it is in the cumulative Completed figures. –  Martin Smith Apr 6 '12 at 12:45

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.