Watching Optimisation Phases with Trace Flag 8675

When a query is executed a few things happen; the query is parsed, a logical tree of the query is created, the query is simplified and then the optimiser determines if a trivial plan can be used. If a trivial plan can't be used, essentially if the optimiser has to figure out the optimal execution plan (such as making decisions on joins) then the query is passed to the full optimisation stage.

The full optimisation stage is where the optimiser uses a bag of tricks to optimise our query (surprise, surpise), well technically it has three bags of tricks that are named optimisation phases that each contain a collection of transformation rules (which I cover in this post that you should never do). The optimiser is not limited to using just one of the phases and each has a set criteria which determines if the optimiser can use that particular phase.

In order to see what how the optimiser is using these phases we need to enable Trace Flag 8675 as well as Trace Flag 3604 which will redirect the output to the query messages tab in Management Studio:

DBCC TRACEON(8675, -1); 

DBCC TRACEON(3604, -1);

Let's start with a very straightforward query on the AdventureWorks2019 sample database and for each of the queries we can actually run them or show the estimated execution plan which will still use the query optimisation process:

SELECT * FROM Person.Person OPTION (RECOMPILE);

Which when I check the output in the messages tab I can the following:

End of simplification, time: 0 net: 0 total: 0 net: 0

End of post optimization rewrite, time: 0 net: 0 total: 0 net: 0.001

End of query plan compilation, time: 0 net: 0 total: 0 net: 0.001

For this query we don't see any information relating to optimisation phases, that's expected because for this query the optimiser has used a trivial plan, which we can check in the plan properties:

If we re-run the query excluding the OPTION (RECOMPLILE) and again check the messages tab we don't see anything in the messages tab this time. This is because the query has been retrieved from the plan cache or procedure cache as it is also known. 

Now I'll add a join to the query to give the optimiser something to think about and use the RECOMPILE option to ensure the query is not retrieved from cache:

SELECT * FROM Person.Person per
INNER JOIN Sales.Customer cus ON cus.PersonID = per.BusinessEntityID
OPTION (RECOMPILE);

This time in the messages output we can see a line for search(1) which is also knowns as the Quick Plan optimisation phase:

End of simplification, time: 0.002 net: 0.002 total: 0 net: 0.002

end exploration, tasks: 57 no total cost time: 0.001 net: 0.001 total: 0 net: 0.004

end search(1),  cost: 3.99696 tasks: 211 time: 0.002 net: 0.002 total: 0 net: 0.006

End of post optimization rewrite, time: 0 net: 0 total: 0 net: 0.006

End of query plan compilation, time: 0 net: 0 total: 0 net: 0.007

Here we can see that the optimiser has produced an execution plan with a cost of 3.9969 and I can check that against either the estimated or actual plan in management studio by hovering over the left most operator (in this case the Select) and checking the Subtree cost, the below image is from the estimated plan showing the estimated cost to be 3.99696

In order to demonstrate the optimiser using multiple phases I'll add a join to another table. There is another optimisation phase, search(0) named Transaction Processing where the transformation rules are used for OLTP type queries. The optimiser didn't start with search(0) for our previous query because there has to be at least three tables used in the query in order for the optimiser to use this particular phase.

SELECT * FROM Person.Person per

INNER JOIN Sales.Customer cus ON cus.PersonID = per.BusinessEntityID

INNER JOIN Sales.SalesOrderHeader soh ON soh.CustomerID = cus.CustomerID 

OPTION (RECOMPILE);

Again using the RECOMPILE this time we're using three tables in the query (Person.Person, Sales.Customer and Sales.SalesOrderHeader) and if we look at the message output after the query has executed we can see the use of two optimisation phases; search(0) and search(1) and corresponding time that the optimiser has spent in each phase:

End of simplification, time: 0.004 net: 0.004 total: 0 net: 0.004

end exploration, tasks: 71 no total cost time: 0.005 net: 0.005 total: 0 net: 0.01

end search(0),  cost: 14.5642 tasks: 386 time: 0.008 net: 0.008 total: 0 net: 0.018

end exploration, tasks: 572 Cost = 14.5642 time: 0.002 net: 0.002 total: 0 net: 0.021

end search(1),  cost: 6.57863 tasks: 1027 time: 0.01 net: 0.01 total: 0 net: 0.031

End of post optimization rewrite, time: 0 net: 0 total: 0 net: 0.032

End of query plan compilation, time: 0.002 net: 0.002 total: 0 net: 0.035

The interesting thing here is the cost difference between the optimisation phases, the search(0) phase returned a query plan with a cost of 14.5642 however by using the search(1) phase the query has used a plan with an associated cost of 6.57863 which is a clear improvement.

There is another phase, stage(2) which is the full optimisation phase that contains every single transformation rule available. I'll cover that in a forthcoming post and in the meantime I'll write a horrible enough query to use that phase and we'll look into optimiser timeouts as well.

Trace Flag 8675 is one of those little known trace flags (IMO) that gives us some in-depth information on how the query optimiser is working. 

To finish off, to disable the trace flags I should now run the following: 

DBCC TRACEOFF(8675, -1); 

DBCC TRACEOFF(3604, -1);