Tuesday, September 24, 2013

Exploring Trace Flag 4199 with SQL Server 2012 Querytraceon Part 1

Trace flag 4199 is a rollup trace flag, which will enable a large number of query optimizer fixes that are otherwise individually enabled by separate trace flags.
More information on the query optimizer behavior related to trace flag 4199 here, including individual kb numbers and links for the rolled-up stuff.
http://support.microsoft.com/kb/974006

Querytraceon has now been publicly documented, and trace flag 4199 is one of the flags listed as supported with querytraceon.
http://support.microsoft.com/kb/2801413

Game on!

The SQL Server version: Microsoft SQL Server 2012 - 11.0.2332.0 (X64)
In query executions with and without trace flag 4199 below, I used 'SET STATISTICS IO ON' in order to get physical/logical reads, etc. 
I repeated the tests until I got a run with and without OPTION (QUERYTRACEON 4199) that had all data in cache and performed no physical reads.
That way the comparison was a little more straightforward - neither execution had any IO waits if neither performed any physical reads.

The test query executions returned 68 rows - this known resultset size allowed easy retrieval of information from sys.dm_exec_query_stats.

So... in SQL Server 2012 two executions of a complex query, differing only by inclusion of trace flag 4199 to for query optimizer behavior.
Without trace flag 4199, there were almost 10 times as many logical reads.  Without trace flag 4199, there was over 10 times as much accumulated worker time.
For the queries I spend most of my time with, trace flag 4199 merits consideration - if not as a global trace flag, certainly at the query level for those queries whose performance needs improvement.

I'm sure that just the io statistics and the query stats won't satisfy many as a full exploration of trace flag 4199 behavior with respect to this query.  I'll also compare the "actual plan" xml to see if I can locate where the significant difference in logical IOs occurs.  But not today.  Otherwise... how would I get you to come back to my blog, dear read?
:) 

(68 row(s) affected)
Table 'DIM_1'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_2'. Scan count 0, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_3'. Scan count 0, logical reads 136, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_4'. Scan count 1, logical reads 204, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'FACT_DETAIL'. Scan count 2761, logical reads 8405, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'FACT_1'. Scan count 409, logical reads 1635, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_5'. Scan count 4, logical reads 138, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_6'. Scan count 0, logical reads 1008, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'FACT_2'. Scan count 0, logical reads 1671, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row(s) affected)


(68 row(s) affected)
Table 'DIM_1'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_2'. Scan count 0, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_3'. Scan count 0, logical reads 136, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_4'. Scan count 1, logical reads 204, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'FACT_DETAIL'. Scan count 28038, logical reads 84834, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'FACT_1'. Scan count 2150, logical reads 7309, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_5'. Scan count 0, logical reads 990, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DIM_6'. Scan count 0, logical reads 2378, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Worktable'. Scan count 1, logical reads 28246, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'FACT_2'. Scan count 1, logical reads 5852, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row(s) affected)


SELECT
   last_execution_time AS exec_time,
   last_logical_reads AS logical_rds,
   last_worker_time AS worker_time,
   last_elapsed_time AS elapsed_time
FROM
   sys.dm_exec_query_stats
WHERE
   last_rows = 68


              exec_time  logical_rds  worker_time  elapsed_time

2013-09-24 22:33:26.000        13211       138990        603339
2013-09-24 22:35:29.030       130019      1913968       4098876

No comments:

Post a Comment