Sunday, February 17, 2019

SQL Server 2016 SP2 CU4/2017 CU13 Access Violation on Certain Autostats Updates

***** Updated 2019-02-18 This post was originally published on February 17th, 2019. February 18 it was updated with some details re: SQL Server 2016 SP2 CU3 and CU5 - the CUs immediately preceding and following the CU4 with the av. The repro has been updated from repro version 58 to repro version 62. This version does a better job of giving results which can easily be compared across CU3, CU4, and CU5. *****

I spent a lot of time tracking this error down.

When I started investigating, the error was known only as an access violation, preventing some operations related to data cleansing or fact table versioning.

It occurred deep within a series of stored procedures.  The execution environment included cross-database DELETE statements, cross-database synonyms, lots of SELECT statements against system views, scalar UDFs, and lots and lots of dynamic SQL.

And... I don't have access to the four systems where the access violation occurred.

I was able to have some investigation performed on those systems - we learned that by disabling 'auto stats update' for the duration of the sensitive operations, the error was avoided.  We also learned that reverting a system from SQL Server 2016 SP2 CU4 to SP2 CU2 avoided the errors.  On those systems, reverting to SP2 CU2 or temporarily disabling 'auto stats update' were sufficient temporary mitigations.

So I set out to reproduce the errors on my laptop.  That took a while.  A pretty long while. 😱

And once I was able to reproduce the access violation, I generated 16 errors and suddenly couldn't get anymore errors!  (I'd later learn that changing the database recovery model from 'simple' to 'full' was the reason the errors were no longer occurring.)  I opened a premier support ticket with Microsoft describing the issue and attaching the sqldump files, and explaining I wasn't able to continue generating the errors.

Fortunately it was only a few hours later that I was able to start generating errors again by proceeding through my process of reproducing errors and simplifying the context much more carefully than previously.

At the bottom of this post is a minimal reproduction of the access violation error in SQL Server 2016 SP2 CU4.  As is, the statements will create a new database t1 with simple recovery mode and 'auto stats update' enabled.  Those are the system state requirements for the access violations.  If you recreate the error yourself, please be aware a memory dump will be created.

The execution context required for the access violation requires a stats object that is already created but empty.  So a stats object for a clustered index(or primary key clustered index) on a table that was just created, or has been truncated.  The underlying column must be BIGINT data type.  With INT, the error does not occur (or at least doesn't occur until a much higher threshold of activity).

Within the same explicit transaction, at least 1024 rows are inserted into the table using the TABLOCK or TABLOCKX hint (without a hint no error will occur), and then a query requests the stats (resulting in the auto-update stats activity).  Then the access violation occurs.

If you'd like to follow along, here is the repro code.

DECLARE @version NVARCHAR(50) = N'SQL Server ' + CONVERT(NVARCHAR(20), SERVERPROPERTY('ProductVersion')) 
SELECT [version] = @version 
PRINT @version
USE [master]
DECLARE @dpath NVARCHAR(200), @lpath NVARCHAR(200), @dbcmd NVARCHAR(1000);
SELECT @dpath = CONVERT(NVARCHAR(100), SERVERPROPERTY('InstanceDefaultDataPath')) + N't1.mdf';
SELECT @lpath = CONVERT(NVARCHAR(100), SERVERPROPERTY('InstanceDefaultLogPath')) + N't1_log.ldf';

SET @dbcmd = N'CREATE DATABASE [t1] ON PRIMARY (NAME = ''t1'', FILENAME = N''' + @dpath + N''', SIZE = 8192KB , MAXSIZE = 1GB, FILEGROWTH = 65536KB )'
SET @dbcmd = @dbcmd + N' LOG ON ( NAME = N''t1_log'', FILENAME = N''' + @lpath + N''', SIZE = 8192KB , MAXSIZE = 1GB , FILEGROWTH = 65536KB );'
EXEC (@dbcmd)
USE t1
SELECT repro_id = 'x62';
PRINT 'repro_id = x62'
/* both DROP and CREATE TABLE can be replaced with
   access violation takes place for empty stat either way */

CREATE TABLE x  ( col1 BIGINT -- No error if INT rather than BIGINT
                  INDEX ci_x CLUSTERED (col1) -- stats on CI or PKCI for access violation on auto stats update
--                index i_col1(col1)) -- nope, no av if stats accompany non-clustered index
--CREATE STATISTICS s_col1 ON x(col1); -- nope, no error if stats on non-indexed column
                                       -- only auto stats update of stats on CI or PKCI seems to hit AV
--Transaction can include or exclude CREATE TABLE but must include INSERT and request for auto stats update

  ;WITH u0 AS (SELECT num=1 UNION ALL SELECT num=1),             -- 2 rows
        u1 AS (SELECT num=1 FROM u0 AS n1 cross apply u0 AS n2), -- 2 * 2 = 4 rows
        u2 AS (SELECT num=1 FROM u1 AS n1 cross apply u1 AS n2), -- 4 * 4 = 16 rows
        u3 AS (SELECT num=1 FROM u2 AS n1 cross apply u2 AS n2), -- 16 * 16 = 256 rows
        u4 AS (SELECT num=1 FROM u3 AS n1 cross apply u1 AS n2), -- 256 * 4 = 1024 rows
  INSERT INTO x WITH ( TABLOCKX ) -- TABLOCK or TABLOCKX to get av; no hint no error
  SELECT TOP (1024) num -- no av if less than 1024 rows
  FROM nums;

  --SELECT result = COUNT (DISTINCT col1) FROM x -- stats auto update in CU3, CU4 or CU5; but no av
  SELECT result = COUNT ( * ) FROM x -- stats auto update in 2016 SP2 CU4 but not CU3 or CU5 
  /* access violation takes place when auto update stats is attempted in 2016 SP2 CU4 */

USE [master]

Here's what the output of the repro code below looks like on SQL Server 2016 SP2 CU3.  Not terribly exciting.  Note that at the end of execution, the stats for ci_x are still empty.  That makes sense - a count(*) from a table can't really benefit from stats.  It doesn''t have an operator accumulating results over time or anything else requiring a memory grant.  Doesn't have a join operator requiring a row estimate.

Indeed, the results look identical in SQL Server 2016 SP2 CU5.  No auto stats update, no error, stats still empty as the code completes.

But what happens in SQL Server 2016 SP2 CU4?  Just after the rows are inserted - and before the results of the count(*) are returned - the query encounters an access violation.

The exception.log file in the SQL Server error log directory looks nice and orderly from these access violations :-)

And  here's the short stack dump included in the SQLDump****.txt files.

It really looks like SQL Server 2016 SP2 CU4 is a loner in this regard - asking for an auto stats update in a context where the stats are immaterial to the query itself.

We'll see.  If there is a fix forthcoming in SQL Server 2016 SP2 CU6 or beyond, I'll update this post with a reference to it.  Perhaps instead I'll learn that this issue was coincidentally fixed in SQL Server 2016 SP2 CU5.  I've looked through the CU5 kbar a few times and didn't see anything I thought was related.

I tried to document within the repro code potential 'bandaid' workarounds if you run into this access violation - just something to tide you over till can upgrade to a fixed version.  For example, switching to full recovery model or disabling auto stats update.  Unfortunately, innocculating against these AVs at the system level may come at too great of a risk in some cases.  There are workarounds possible in the code as well.  Eliminating hints in the insert might work without unreasonable cost.  Alternatively a manual stats update before the count(*) may be acceptable.

All right - that's it for now! Ciao!! 

***** Addendum 20190220 *****
I decided to check SQL Server 2017 as well.  CU11 - no error.  CU12 - no error.

So be on the lookout for this access violation in SQL Server 2016 SP2 CU5 and SQL Server 2017 CU13.

Monday, January 14, 2019

Evaluating SQL Server System Resource Governor Workload Group "Maximum Memory Grant %" for Adjustment

I'm looking at a SQL Server system with 4 NUMA nodes, 18 cores on each NUMA node.  Total RAM: 2 TB.

We can easily verify that the SQL Server default workload group is the main CPU consumer on the server.

I like to trend active requests and parallel threads against CPU utilization.  On the systems I watch, when they are healthy there should be a fairly strong correlation between CPU and requests, or CPU and parallel threads, or both.  Hm. During this time, threads have a stronger correlation than requests.  That's not concerning by itself.  But with this many requests and this many parallel threads against 72 logical processors/schedulers (HT is not enabled), I want higher CPU utilization and a higher rate of work.

Either the work is poorly distributed (a less likely condition) or there is a wait type (or types) that can be identified as suppressing CPU utilization.

Perfmon captures some wait types, and I strike gold by looking at resource_semaphore waits. 

I don't like switching between area and line graphs for resource utilization, but the graph below is easiest to read with CPU as a line graph over stacked area graphs of memory grants (pending and outstanding).  The point of this graph is to show if, at every point in time, the pending memory grants were converted to outstanding (so that the query was executing rather than waiting) there would be enough CPU to allow the queries to run.  When I intervene on a system for scalability or performance, I hope not just to replace one wait type with another 😎.  If, for example, CPU was near 100% utilized while there were pending memory grants, I'd expect simply to replace resource_semaphore waits with SOS_scheduler waits.  But, that's not the case here.

So I have in mind to lower the "Maximum Memory Grant %" for the relevant workload group.  On this system, the default workload group is still using 25%.

The graph below has reserved memory in dark blue layered in front of granted memory in lighter blue.  (There really is only one active user workload group on this system - default.  If there were additional workload groups and/or additional resource pools this type of analysis is still possible but information from DMVs would be necessary to augment perfmon.) So the exposed light blue on the top is the amount of used granted query memory.  Its just a fraction of the granted memory and sometimes a quite small fraction at that.  By reducing the maximum memory grant percentage, there will be a better fit between granted and used query memory (eg I expect reserved memory to be lower zs well as granted memory at the same query concurrency.) 

But there are lots of queries running on the system.  Some of them are probably already spilling to tempdb.  Those queries will spill more by lowering the max memory grant percent.  And some queries that weren't spilling before but were close will start spilling into tempdb.

Let's look at how much tempdb was already in use.  Perfmon has counters for the data file size in tempdb, and the amount of tempdb used.  In the graph below the used tempdb is in light blue layered in front of the dark blue size of tempdb files.  So the exposed dark blue at the top is the used tempdb.

Let's do the subtraction for used query memory, and used tempdb.  And stack them on top of each other.  The upper border is the upper limit for sort/hash activity on the system at any given time.  (Upper limit because "used tempdb" also includes temp tables, version store, etc).

Assuming that all of the queries from 10:00 am to 6:00 pm ran with the same plans but with maximum memory grant percent at 6% rather than 25%, none of their sort/hash needs would change.  Assuming the pace of every query remained the same, eliminating only resource_semaphore wait time (that's not realistic but work with me here 😇) the total area under the upper border would stay constant.  Like moving tetris blocks around.  The share of tempdb is likely to increase vs used query memory.  But it looks like bringing the maximum query memory grant percent down from 25% to 6% is going to be a win for this workload.  After the change, I recommend doing the same type of analysis to make sure the behavior is as expected.

Thursday, December 6, 2018

Fun with SQL Server Plan Cache, Trace Flag 8666, and Trace Flag 2388

Ok, last one for a while.  This time, pulling the stats relevant to a plan from the plan XML in the plan cache (thanks to trace flag 8666), then getting a little bit of stats update history via trace flag 2388.

I'm not particularly happy with performance; it took between 10 and 12 seconds to return a 12 row resultset 😥

But its good enough for the immediate troubleshooting needs.

Some sample output is below; note that the output is sorted by database, schema, table, and stats name.  But the updates of any one stat are NOT sorted based on the date in [Updated].  I don't have the brainpower right now to figure out how to convert the [Updated] values to DATETIME to get them to sort properly.  Maybe sometime soon 😏

CREATE OR ALTER PROCEDURE sasquatch__hist_one_plan_stats_T8666 @plan_handle VARBINARY(64)
/* stored procedure based on work explained in the following blog post

supply a plan_handle and if trace flags 8666 was enabled at system level or session when plan was compiled
and trace flag 2388 is enabled at session level when stored procedure is executed, recent history of stats used to compile the plan will dsiplayed

DECLARE @startdb NVARCHAR(256),
        @db      NVARCHAR(256),
        @schema  NVARCHAR(256),
        @table   NVARCHAR(256),
        @stats   NVARCHAR(256),
        @cmd     NVARCHAR(MAX);
SET @startdb = DB_NAME();

SELECT CONVERT(XML, query_plan) planXML
FROM sys.dm_exec_query_plan(@plan_handle);

SELECT DbName.DbName_Node.value('@FieldValue','NVarChar(128)')              dbName,
       SchemaName.SchemaName_Node.value('@FieldValue','NVarChar(128)')      schemaName,
       TableName.TableName_Node.value('@FieldValue','NVarChar(128)')        tableName,
       StatsName_Node.value('@FieldValue','NVarChar(128)')                  statName,
       CONVERT(INT, NULL) done
INTO #QO_stats
FROM #plan qsp
CROSS APPLY qsp.planXML.nodes(N'//InternalInfo/EnvColl/Recompile')       AS Recomp(Recomp_node)
CROSS APPLY Recomp.Recomp_Node.nodes(N'Field[@FieldName="wszDb"]')       AS DbName(DbName_Node)
CROSS APPLY Recomp.Recomp_Node.nodes(N'Field[@FieldName="wszSchema"]')   AS SchemaName(SchemaName_Node)
CROSS APPLY Recomp.Recomp_Node.nodes(N'Field[@FieldName="wszTable"]')    AS TableName(TableName_Node)
CROSS APPLY Recomp.Recomp_Node.nodes(N'ModTrackingInfo')                 AS [Table](Table_Node)
CROSS APPLY Table_Node.nodes(N'Field[@FieldName="wszStatName"]')         AS [Stats](StatsName_Node)

DROP TABLE IF EXISTS #one_stat_hist;
CREATE TABLE #one_stat_hist
(Updated NVARCHAR(50), [Table Cardinality] BIGINT, [Snapshot Ctr] BIGINT, 
 Steps INT, Density FLOAT, [Rows Above] BIGINT, [Rows Below] BIGINT, 
 [Squared Variance Error] NUMERIC(16,16), [Inserts Since Last Update] BIGINT, 
 [Deletes Since Last Update] BIGINT, [Leading Column Type] NVARCHAR(50));


 CREATE TABLE #stats_hist
(dbName NVARCHAR(50), schemaName NVARCHAR(50), tableName NVARCHAR(50), statName NVARCHAR(50),
 Updated NVARCHAR(50), [Table Cardinality] BIGINT, [Snapshot Ctr] BIGINT, 
 Steps INT, Density FLOAT, [Rows Above] BIGINT, [Rows Below] BIGINT, 
 [Squared Variance Error] NUMERIC(16,16), [Inserts Since Last Update] BIGINT, 
 [Deletes Since Last Update] BIGINT, [Leading Column Type] NVARCHAR(50));

     SELECT TOP 1 @db = dbName, @schema = schemaName, @table = tableName, @stats = statName
     FROM #QO_stats
     WHERE done IS NULL
     ORDER BY dbName, schemaName, tableName, statName;

     SET @cmd = N'USE ' + @db + N' DBCC SHOW_STATISTICS(''' + @schema + N'.' + @table + N''', ' + @stats 
              + N') WITH NO_INFOMSGS'

     INSERT INTO #one_stat_hist
     EXEC (@cmd);

  INSERT INTO #stats_hist
  SELECT @db, @schema, @table, @stats, *
  FROM #one_stat_hist;

     UPDATE #QO_stats
     SET done = 1 
     WHERE @db =   #QO_stats.dbName
     AND @schema = #QO_stats.schemaName
     AND @table =  #QO_stats.tableName 
     AND @stats =  #QO_stats.statName;

     TRUNCATE TABLE #one_stat_hist;


SELECT * FROM #stats_hist ORDER BY dbName, schemaName, tableName, statName

EXEC (N'USE ' + @startDB);

/* 20181206 */