More things you shouldn't do in SQL Server: Disabling Optimisation Phases

PLEASE DON'T DO THIS

In my last post I covered optimisation phases and we can view optimiser information by using Trace Flag 8675. The last post looked at the search(0) and search(1) phases and we saw how the optimiser improved the cost of the query by using both of the phases with the search(1) phase resulting in the better plan in terms of cost.

I mentioned in that post that the optimiser has another phase it can use, no surprise it's called search(2) also known as the full optimisation phase (yes that's the full optimisation phase of the full optimisation stage, still with me? Good!).

The full optimisation phase I suppose would normally be reserved for those beastly queries that the optimiser really has to get to work on, looking at you Entity Framework but we can force optimiser behaviour by using an undocumented trace flag 8677 which entirely skips the search(1) phase. 

Now it has to be said it's undocumented for a reason, the reason is that it's really not a good idea to do this. In fact enabling this trace flag is such a bad idea that it will probably cause no end of issues with query performance...so let's do it, but before we do let me add yet again that please don't do this! Disabling optimisation features is a really bad idea, just like we did in this post - the purpose for this demo is just to show that we can, and how dangerous it can get.

Right, on with the show...

DBCC TRACEON(3604, -1);

DBCC TRACEON(8675, -1); 

DBCC TRACEON(8677, -1); 

As in the last post I've enabled trace flags 3604 and 8675 and this time I've also enabled trace flag 8677. I'm going to run the following query as it won't be able to use the search(0) phase as it's only using two tables and the search(0) phase requires at least three tables in the query:

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

The last time we ran the query (or we can look at the estimated execution plan) the output was the following:

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

This time though because we've disabled the search(1) phase we get this instead:

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

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

end search(2),  cost: 3.99696 tasks: 211 time: 0.001 net: 0.001 total: 0 net: 0.002

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

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

We can see the trace flag has worked, search(1) has been skipped and instead it has used the search(2) optimisation phase and apart from a very slight difference in compilation time the result is exactly the same which is no surprise as the search(2) phase contains all the transformation rules that can be used by the optimiser.

Let's try the query that is using three tables: 

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);

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

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

end search(0),  cost: 14.5642 tasks: 386 time: 0.001 net: 0.001 total: 0 net: 0.003

end exploration, tasks: 582 Cost = 14.5642 time: 0 net: 0 total: 0 net: 0.003

end search(2),  cost: 6.57863 tasks: 1059 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

Again we see the same as the previous post, the optimiser has used two phases and we can see the cost improvement gained between the search(0) and this time the search(2) phase. But at this point I'm wondering that if we can skip search(1), can we disable the others as well?

Yes we can (insert evil laugh here).

Trace flag 8677 also some, 8670 to skip search(2) and 8750 to skip search(0). Again, don't do this...ever!! Let's start with 8670:

DBCC TRACEON(8670, -1); 

As expected, because SQL won't even give me a warning, probably because it thinks nobody in their right mind would do this, the search(2) has been skipped which has resulted in a query that has a higher cost than if it could have used either search(1) or search(2):

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

end exploration, tasks: 71 no total cost time: 0.001 net: 0.001 total: 0 net: 0.002

end search(0),  cost: 14.5642 tasks: 386 time: 0.001 net: 0.001 total: 0 net: 0.003

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

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

So what happens if we disable search(0) I can hear you asking?? 

DBCC TRACEON(8750, -1); 

And when I try to run the query again:

Msg 8624, Level 16, State 1, Line 8

Internal Query Processor Error: The query processor could not produce a query plan. For more information, contact Customer Support Services.

Well it seems we've broken it (you notice I've used "we've" there) - query optimisation has essentially been disabled, as we say in Yorkshire, it's well and truly knackered.

If anything it's shown how easy it can be to enable a couple of undocumented things and cause no end of problems and a SQL Server that isn't working any more. Interestingly enough even if I remove the OPTION (RECOMPILE) which should retrieve the query from cache I still get the error. In order to set things right in the universe I'll quickly disable those trace flags again:

DBCC TRACEOFF(8677, -1); 

DBCC TRACEOFF(8670, -1); 

DBCC TRACEOFF(8750, -1);

DBCC TRACEOFF(8675, -1); 

DBCC TRACEOFF(3604, -1);

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);