SQL Server Query Store: Usability Soft Spots -- Part 2

Part 2 Summary: the stored procedure was modified to no longer use "SELECT... INTO" with a table from tempdb, and to truncate the results table with each iteration rather than drop the table.  Of the initial 19 plan_id values for the test query, only 2 would successfully force from Query Store.  After trying to force all of the plans (including the surprise plans which first showed up and were used while another plan was forced), from the 34 total plan_id values, the tally stood at 17 plans which would successfully force, and 17 plans which would not.

Others in the series:
SQL Server Query Store: Usability Soft Spots -- Part 1
https://sql-sasquatch.blogspot.com/2019/06/sql-server-query-store-usability-soft.html

~~~~~

Yesterday I started a blog post series.

SQL Server Query Store: Usability Soft Spots -- Part 1 

https://sql-sasquatch.blogspot.com/2019/06/sql-server-query-store-usability-soft.html

One of my goals for problem repros is to eliminate as many extraneous vulnerable points as possible.  For example, when reproducing a problem with Query Store plan forcing, I want to remove as many known or suspected plan forcing issues as possible, other than the issue the repro is meant to draw attention to.

Erin Stellato pointed out that temp tables are associated with some atypical plan forcing behavior.  Dropping of tables, indexes, or statistics can also result in atypical plan forcing behavior.

For these reasons I've reworked the repro which I'll be building on in these blog posts.

In my initial blog post, the test query used "SELECT... INTO" with a temp table.

The new version of the repro contains a CREATE TABLE statement before the test query, and no longer uses a temp table.

I'm still creating the test database the same way.

USE [master]
GO
CREATE DATABASE [surprise_plan]
 ON  PRIMARY 
( NAME = N'surprise_plan', FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL15.CTP_3_0__2019\MSSQL\DATA\surprise_plan.mdf' , SIZE = 139264KB , MAXSIZE = UNLIMITED, FILEGROWTH = 65536KB )
 LOG ON 
( NAME = N'surprise_plan_log', FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL15.CTP_3_0__2019\MSSQL\DATA\surprise_plan_log.ldf' , SIZE = 270336KB , MAXSIZE = 2048GB , FILEGROWTH = 65536KB )
 WITH CATALOG_COLLATION = DATABASE_DEFAULT
GO
ALTER DATABASE [surprise_plan] SET  MULTI_USER 
GO
ALTER DATABASE [surprise_plan] SET QUERY_STORE = ON
GO
ALTER DATABASE [surprise_plan] SET QUERY_STORE (OPERATION_MODE = READ_WRITE, CLEANUP_POLICY = (STALE_QUERY_THRESHOLD_DAYS = 30), DATA_FLUSH_INTERVAL_SECONDS = 60, INTERVAL_LENGTH_MINUTES = 1, MAX_STORAGE_SIZE_MB = 1000, QUERY_CAPTURE_MODE = ALL, SIZE_BASED_CLEANUP_MODE = AUTO)
GO
ALTER DATABASE [surprise_plan] SET  READ_WRITE 
GO

The stored procedure follows the same type of strategy.  Note there are now two parameters. @testQuery_reps indicates how many instances of the test query will be executed.  In addition to the test query itself, the stored procedure executes some additional queries to increase the rate of change in the Query Store structures.  @filler_reps indicates how times the 'filler query' section of code will execute.

USE [surprise_plan]
GO
CREATE OR ALTER PROCEDURE [dbo].[surprise_plan2test] @testQuery_reps INT, @filler_reps INT = 2
AS
SET NOCOUNT ON
DROP TABLE IF EXISTS sq__surprise_plan_tests;
CREATE TABLE sq__surprise_plan_tests(
     query_id BIGINT,
     query_hash BINARY(8),
     plan_id BIGINT,
     query_plan_hash BINARY(8),
     runtime_stats_id BIGINT,
     count_executions BIGINT);

DECLARE @ij INT = 0, @query_count INT, @sqlcmd2 NVARCHAR(MAX), @sqlcmd NVARCHAR(MAX) =
'INSERT INTO sq__surprise_plan_tests
 SELECT /*surprise2test*/ qsq.query_id, qsq.query_hash, qsp.plan_id,

        qsp.query_plan_hash, qsrs.runtime_stats_id, qsrs.count_executions
 FROM sys.query_store_runtime_stats qsrs
 JOIN sys.query_store_plan qsp ON qsrs.plan_id = qsp.plan_id
 JOIN sys.query_store_query qsq ON qsp.query_id = qsq.query_id
 JOIN sys.query_store_query_text qsqt ON qsq.query_text_id = qsqt.query_text_id
 WHERE qsqt.query_sql_text LIKE ''%surprise2test%''
 ORDER BY qsrs.runtime_stats_id DESC;' 

WHILE @testQuery_reps > 0
BEGIN
     TRUNCATE TABLE sq__surprise_plan_tests;
     DBCC FREEPROCCACHE WITH no_infomsgs;
     EXEC (@sqlcmd);
     SET @ij = 0;
     WHILE @ij < @filler_reps
     BEGIN
          SELECT TOP 1 

@sqlcmd2 = 'SELECT TOP (1) plan_id INTO #tmp 
                             FROM SYS.QUERY_STORE_RUNTIME_STATS 
                             WHERE runtime_stats_interval_id = '
                             + CONVERT(NVARCHAR(10), ((query_id - 1) * @testQuery_reps) + @ij) + ';
                             DROP TABLE IF EXISTS #tmp;'
          FROM sys.query_store_query

          WHERE @testQuery_reps = @testQuery_reps AND @ij = @ij
          ORDER BY query_id DESC;

EXEC (@sqlcmd2);
          SET @ij = @ij + 1;
     END 

     SELECT @testQuery_reps = @testQuery_reps - 1;
END

SELECT * FROM sq__surprise_plan_tests
ORDER BY runtime_stats_id DESC;

Ok.  Let's execute the test query 1600 times, with each iteration of the test query submission accompanied by two iterations of the filler query section of code.

EXEC [dbo].[surprise_plan2test] @testQuery_reps = 1600, @filler_reps = 2;

The result... 19 unique plan_id values for the query from 1600 executions.

So let's take a look in the "Tracked Queries" Query Store activity.

Interesting that the order of plan_id values in the right-hand legend is immediately sensible.  Let's see what happens when I force plan_id 2...

I execute the test query again twice, with 1 time 'round for the filler queries. I could execute the test query a single time but I like it when the new plans show up in the query results the test query returns... due to timing issues that is reliable when the test query is executed twice but not when the test query is executed a single time only.

EXEC [dbo].[surprise_plan2test] @testQuery_reps = 2, @filler_reps = 1;

Well look at that! At the top of the results list is plan 3220 now.

Let's refresh the "Tracked Queries" activity.

Ohhhh.  I forced plan_id 2 (in the purple box below) but what showed up was plan_id 3220 (in the yellow box below).

Ok, that's weird.  Did a last_force_failure_reason_desc show up for plan_id 2?

SELECT plan_id, query_id, engine_version, compatibility_level,  
       is_forced_plan, last_force_failure_reason_desc
FROM sys.query_store_plan WHERE plan_id = 2;

Hm.  So I forced plan_id 2, but plan_id 3220 showed up instead.  And there is no last_force_failure_reason_desc for plan_id 2.

Kendra Little uses the term “morally equivalent plan” in some excellent blog posts, mentioning that the term likely came from Conor Cunningham via Erland Sommarskog.
I've listed those blog posts below, as well as a related Azure Feedback suggestion.

Forced Plan Confusion: Is_Forced vs Use Plan = True
https://sqlworkbooks.com/2018/03/forced-plan-confusion-is_forced-vs-use-plan-true/

What is a “Morally Equivalent Execution Plan,” and Why Is It Good?
https://sqlworkbooks.com/2018/03/what-is-a-morally-equivalent-execution-plan-and-why-is-it-good/

Indicate “morally equivalent” forced plan where use_plan = true but is_forced = 0
https://feedback.azure.com/forums/908035-sql-server/suggestions/33562136-indicate-morally-equivalent-forced-plan-where-us

So... something funky happened when I tried to force plan_id 2.  What if I try forcing the other plans for query_id 2?

Here's a grid of the plan_id values selected for execution after forcing each originally available plan_id for query_id 2.

Of 19 query plans available from the first 1600 executions of the test query, only two plan_id values were able to be successfully forced: 292 and 501.  Seventeen of the original plan_id values were not selected by the optimizer after they were forced from Query Store. That seems like the cards are stacked against me.

But as the plan_id values were forced, new plans appeared.  Plenty of them LoL.  If I add in the new plans and attempt to force them as well...

So, with all 34 of the plans in scope, it's a 50-50 chance.  17 of the original plans wouldn't force, 2 of them would.  Add in 15 surprise plans, and there are 17 plans that won't force and 17 plans that do force successfully. And the "Tracked Queries" activity now looks like...

 
Ok.  So with this example I hope I've shown that, at least as through SQL Server 2019 CTP 3.0, encountering a “morally equivalent plan” choice after Query Store forcing a plan might not be as rare as commonly held.

If you're still with me, I've still got a little ways to go with this one... next installment won't be at least until tomorrow, though.

Thanks for reading!

Ciao!!

Q

SQL Server Query Store: Usability Soft Spots -- Part 1

Part 1 Summary: pretty easy to get lots of Query Store plan_id values per query_id, and sometimes the sort of plan_id values in "Tracked Queries" is downright unhelpful.

SQL Server Query Store: Usability Soft Spots -- Part 2
https://sql-sasquatch.blogspot.com/2019/06/sql-server-query-store-usability-soft_16.html
~~~~

For now, I'm working with a Developer Edition SQL Server 2019 CTP 3.0 installation, on my laptop.

No global trace flags enabled.  Pretty vanilla.

 
OK, let's create a database just for this series of blog posts. No tricks up my sleeve, enable Query Store out the gate, change QUERY_CAPTURE_MODE from default AUTO to ALL, DATA_FLUSH_INTERVAL_SECONDS = 60 and INTERVAL_LENGTH_MINUTES = 1 because these will be pretty quick tests.

USE [master]
GO
CREATE DATABASE [surprise_plan]
 ON  PRIMARY 
( NAME = N'surprise_plan', FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL15.CTP_3_0__2019\MSSQL\DATA\surprise_plan.mdf' , SIZE = 139264KB , MAXSIZE = UNLIMITED, FILEGROWTH = 65536KB )
 LOG ON 
( NAME = N'surprise_plan_log', FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL15.CTP_3_0__2019\MSSQL\DATA\surprise_plan_log.ldf' , SIZE = 270336KB , MAXSIZE = 2048GB , FILEGROWTH = 65536KB )
 WITH CATALOG_COLLATION = DATABASE_DEFAULT
GO
ALTER DATABASE [surprise_plan] SET  MULTI_USER 
GO
ALTER DATABASE [surprise_plan] SET QUERY_STORE = ON
GO
ALTER DATABASE [surprise_plan] SET QUERY_STORE (OPERATION_MODE = READ_WRITE, CLEANUP_POLICY = (STALE_QUERY_THRESHOLD_DAYS = 30), DATA_FLUSH_INTERVAL_SECONDS = 60, INTERVAL_LENGTH_MINUTES = 1, MAX_STORAGE_SIZE_MB = 1000, QUERY_CAPTURE_MODE = ALL, SIZE_BASED_CLEANUP_MODE = AUTO)
GO
ALTER DATABASE [surprise_plan] SET  READ_WRITE 
GO

Now let's create stored procedure [surprise_plan1test] for some fun.  Nothing too clever here.  A query is executed against query store as dynamic SQL.  Do it as dynamic SQL so the offset is predictable and it always matches to the same Query Store query_id as long as context_settings_id stays the same.

USE [surprise_plan]
GO
CREATE OR ALTER   PROCEDURE [dbo].[surprise_plan1test] @max_reps INT
AS
SET NOCOUNT ON
DECLARE @ij INT = 0, @query_count INT, @sqlcmd2 NVARCHAR(MAX), @sqlcmd NVARCHAR(MAX) =
'SELECT /*surprise1test*/ qsq.query_id, qsq.query_hash, qsp.plan_id, qsp.query_plan_hash, qsrs.runtime_stats_id,
                      r_last_execution_time = MAX(qsrs.last_execution_time), r_count_executions = SUM(qsrs.count_executions)
 INTO ##results
 FROM sys.query_store_runtime_stats qsrs
 JOIN sys.query_store_plan qsp ON qsrs.plan_id = qsp.plan_id
 JOIN sys.query_store_query qsq ON qsp.query_id = qsq.query_id
 JOIN sys.query_store_query_text qsqt ON qsq.query_text_id = qsqt.query_text_id
 WHERE qsqt.query_sql_text LIKE ''%surprise1test%''
 GROUP BY qsq.query_id, qsq.query_hash, qsp.plan_id, qsp.query_plan_hash, qsrs.runtime_stats_id
 ORDER BY qsrs.runtime_stats_id DESC, r_last_execution_time DESC;'
SELECT @query_count = COUNT(*) FROM sys.query_store_query;
WHILE @ij < @max_reps
BEGIN
DROP TABLE IF EXISTS ##results;
DBCC FREEPROCCACHE WITH no_infomsgs;
EXEC (@sqlcmd);
SET @sqlcmd2 = 'SELECT TOP (1) * 
INTO #tmp 
FROM SYS.QUERY_STORE_RUNTIME_STATS 
WHERE runtime_stats_interval_id = ' + CONVERT(NVARCHAR(10), @query_count + @ij) + ';
DROP TABLE IF EXISTS #tmp;'
EXEC (@sqlcmd2);
EXEC (@sqlcmd2);
SET @ij = @ij +1;
END
SELECT * FROM ##results
ORDER BY runtime_stats_id DESC;

EXEC [dbo].[surprise_plan1test] @max_reps = 1600

All right.  Let's head over to the Query Store activities. Since I know I'm interested in query_id 4, that's the one I'll pull up.

Yeah. That's a lotta plans in the right-hand legend.  22 of them.  In a not very helpful order.  In fact... though I've tried to figure it out, I don't know what type of order is used for that right-hand legend.  It's not chronological.  It's not based on duration which is the metric displayed by the graph. I dunno.

Usually with a few more executions of query_id 4 and a few refreshes of this activity, the right-legend becomes sorted in descending plan_id from top-to-bottom. And that's pretty durable.  But sometimes it switches back to this nonsensical (to me) ordering.

Got plenty more to show but I wanted to keep this blog post short as an introduction to what I'd be working with.

In the field, I see this quite often - a query_id with over 20 plans that show up in the Tracked Queries activity.  And the unhelpful ordering of plans in the right-hand legend, while a minor and fleeting inconvenience, is usability soft spot number 1. 

For an update to the repro code and the next step in looking at Query Store Usability Soft Spots continue at...
SQL Server Query Store: Usability Soft Spots -- Part 2
https://sql-sasquatch.blogspot.com/2019/06/sql-server-query-store-usability-soft_16.html

Thanks for reading!

Ciao!!

Q