Monday, February 6, 2017

Performance Problem PLUS: A Case of Absurd SQL Server Disk Service Times

An interesting case of perfmon captures came to me last week.  The original question was "What is causing the intermittent extremely high disk latency?"  The graph immediately below shows read and write service times, measure in the VM guest in 30 second perfmon captures.  The guest is a 4 vcpu VM in ESXi 5.5, running SQL Server 2012.

The blue is the read service time average... in full seconds!  And the red is write service time average - again in full seconds!!



That's some astoundingly high disk latency!!  Let's walk through some typical analysis to see if a potential cause becomes clear.

First I see that a single outlier in read service time results in the difference between the sec/read axis label and the sec/write axis label.  By eliminating that outlier, I can graph both read and write service times on the same scale. With read and write latency on the same scale, its more evident that read and write latency are typically elevated in the same perfmon intervals.  Some performance problem spots can cause read and write service time elevation, some will only trouble writes, and some will only trouble reads.  (It's trickier than seems at first glance to recognize these as it sometimes requires splitting graphs for activity vs latency per WIndows logicalDisk or physicalDisk - or even aggregating those numbers for an individual adapter port/vHBA.)  But in this case, it looks like both read and write performance are disrupted by something (or maybe somethings).  



The writes from this server are going to external storage with write cache.  Read performance problems are almost always accompanied by write performance problems in this sample.  So I'll continue by focusing on the write behavior.

Perhaps write throughput in IOPs or bytes/sec is correlated to the write service time?  Nope, doesn't appear to be.

What about total IOPs or total bytes/sec?  Hmmm.  Those look slightly better... maybe.


Now - what if I had looked just at the busiest times to try to diagnose the issue?  The way that the yellow-shaded areas look below, if I narrowed my scope too early to busy disk times, I may certainly have pursued some type of performance issue related to total throughput.


But, looking back again at the entire timeperiod, total bytes/sec doesn't do much to help understand the green-shaded portion - where disk throughput is very low but disk latency is intermittently intolerable. 


What about disk queuing?  That's one of my favorites to blame! Nope.  Not this time.


Now, to be really thorough, each of those cases should be considered on a Windows volume basis.  I won't drag you through that today, though :-)

And of course, noisy neighbor is always a possibility.  Could be at ESXi host level, or at shared storage due to another tenant there.  Could even be intermittent errors from something in the server or outside the server but in the storage path.  With service times *this* high, some type of error condition and SCSI timeouts would actually be a solid suspicion. But that's not where we're going today. either.

OK.  Let's look at write latency against CPU utilization on the VM.  Hmmm.  Seems I could split that into a very idle period of time until about 2:45 am, a busy time from 2:45 am to about 4:00 am, and another very idle time from 4:00 am on.


I'll actually split those graphs apart.  Here's 12:30 pm on February 1 to 2:44 am on February 2.



Here's 2:45 am to 4:00 am.


And here's 4:00 am onward.  That's an interesting wave in the graph - reminds me of "The Outer Limits" intro.


Let's zero in on a chunk of time from the first period - a little more than 2 hours.  Now that we look more closely.... hey!!!  got an "Outer Limits" wave here, too.  I look at a *lot* of perfmon data. In my professional opinion, that's weird.


OK, zoom in a little more, on those latency Alps.


Let's pick a peak.



Yep, that's totally weird.  Does it make any more sense if we look at individual vcpus?  (Remember - in your VM everything is software.  The scsi adapter is emulated within the VM, the NIC is emulated in the VM, etc) 

Rats.  That was a really good idea, too.  Nothin'.  Or....

(I want to call attention to the change in maximum axis value for CPU utilization.  I nearly *always* use 100% as the maximum value, In these last two graphs I've used a maximum value of 24% because utilization of each of the 4 vcpus is really low and I felt it made the graphs slightly more readable.)



Hey!! Perfmon was collecting 30 second samples.  But two intervals after 2:06:22 is 2:07:52 rather than 2:07:22.  The system lost 30 seconds in the span of a minute.  And two intervals past 2:07:52 is 2:11:22 - the system lost 150 seconds in a minute?

Here's an important maxim: perfmon is only as reliable as the system clock of its accounting.

Its pretty rare these days for a physical server to drift much.  Occasionally time may be corrected after crossing a tolerance threshold.  But this vm seems to have a system clock that is often slowing way down - and then being abruptly corrected.  The abrupt corrections result in lost time.  There are a number of reasons time on a system may drift.  In this case, I suspect that the VM is syncing time with the host rather than syncing time with an NTP source.  Maybe time is drifting even on the ESXi host?

If I find out the exact nature of the system clock problem here, I'll update the post.  Usually its enough to nudge the virtualization admins about the system clock - so I may not hear back once its fixed.

I titled this post "Performance Problem PLUS" intentionally.  This VM still won't have great disk service times once the system clock is fixed - but the extreme outliers should be gone.  It would be flying blind to try to characterize a performance problem from perfmon if the clock can't be trusted.  So... fixing any remaining performance issues will have to be a story for another day.  



*****

Some extra reading in case you happen on one of these cases yourself...

Timekeeping in VMware Virtual Machines
VMware vSphere 5.0, Workstation 8.0, Fusion 4.0

Thursday, January 19, 2017

SQL Server, Dead Connection Detection & Windows Registry Setting TcpMaxDataRetransmissions - What's the real deal?

Dead Connection Detection is an important facet of SQL Server operational database support.  If the client side of a database connection is dead-and-gone, the server side is consuming an ephemeral port, may have an open transaction (and thus be preventing transaction log truncation), may be holding database locks (causing blocking), etc.  The sooner the connection is verified as dead and the database thread cleaned up, the sooner orphaned resources can be dealt with.  On the other hand, if dead connection testing is too aggressive, a sluggish client may not respond to keepalive probes in time and its connection may be closed.  This is a special consideration now for virtual servers involved in batch work.  The nature of their workload, and the "urge to converge" can lead to VMs that are CPU-saturated for short periods of time - aggressive dead connection detection could cause what seem to be network-related failures in these cases.  

TCP supplies a mechanism to handle Dead Connection Detection.  When a TCP port is opened, keepidle functionality can be enabled.  The relevant parameters are the keepidle time, the keepinterval, and the retries. (The names attached to these parameters vary a bit with platform.)  When enabled on a port, the keepidle timer counts down time on an idle connection.  Note - any traffic on the port - even the keepidle probes - resets the timer.  Once the timer reaches zero, a keepidle probe is sent.  If the keepidle probe isn't acknowledged by the other side of the connection within the time specified by keepinterval, another probe is sent.  The number of retries for the keepalive probes is also configurable on many platforms.  If any keepalive probe is ack'd by the other side, the keepalive timer resets (and the remaining probes for that round aren't sent).  If the last probe is sent and not ack'd within the keepinterval, in most cases the connection will be terminated.  In the case of SQL Server, that allows the session ID attached to the port to be terminated and cleaned up as well.  (Here's an important parenthetical: typically, the max number of keepalive probe retries and the max number of retransmits for any TCP packet is controlled by the same parameter.  Keepalive probes use a fixed interval, normal retransmits will double each previous interval until reaching the maximum.)       

The following blog post from 2010 explains Windows registry values KeepAliveTime, KeepAliveInterval, and TCPMaxDataRetransmissions and their roles in dead connection detection.

Things that you may want to know about TCP Keepalives
https://blogs.technet.microsoft.com/nettracer/2010/06/03/things-that-you-may-want-to-know-about-tcp-keepalives/

In SQL Server 2005, a valuable addition was made.  SQL Server would use a "Keep Alive" value specified specifically per instance, rather than the KeepAliveTime specified by the Windows registry.  It defaulted to 30000 ms/30 seconds.

The blog post below explains this new addition, and mentions that the interval for SQL Server will be a fixed 1000 ms/1 second, regardless of the KeepAliveInterval specified in the Windows registry. At the time SQL Server 2005 was introduced, TCPMaxDataRetransmissions from the Windows registries still controlled the maximum number of probes.

Understand special TCP/IP property "Keep Alive" in SQL Server 2005
https://blogs.msdn.microsoft.com/sql_protocols/2006/03/08/understand-special-tcpip-property-keep-alive-in-sql-server-2005/

But!!

Let's look at the following piece of developer-facing documentation.

SIO_KEEPALIVE_VALS control code

"On Windows Vista and later, the number of keep-alive probes (data retransmissions) is set to 10 and cannot be changed."

Huh.  On Windows Vista and later - so that would include Windows Server 2008, Windows Server 2008 R2, Windows Server 2012, Windows Server 2012 R2, and Windows Server 2016.

Its true.  Even though there are lots of places out there that still discuss setting TcpMaxDataRetransmissions in the Windows registry - its for naught.  See a recommendation to set it to 3 from its past default of 5?  Nah.  On Windows Vista and later, you'll get 10 as a max.

In a blog post coming soon, we'll look at TCP protocol properties "Keep Alive" and "Keep Alive Interval" for SQL Native Client 11.0.  I'll also discuss testing methodology, and implications.

*****

Here's a round-up of various documentation that discusses setting TcpMaxDataRetransmissions, without mentioning that from Windows Vista onward this is hardcoded at 10 and cannot be changed.


TechNet Library Windows Server > Windows Server 2008 R2 and Windows Server 2008 > Secure Windows Server
> Threats and Countermeasures Guide: Security Settings in Windows Server 2008 and Windows Vista
> Additional Registry Settings

This entry recommends changing TcpMaxDataRetransmissions from 5 to 3, for Windows Vista.

This page mentions TCPMaxDataRetransmissions for Windows Compact Embedded 2013.

This page about accessing SQL Azure database recommends setting registry value TCPMaxDataRetransmissions to 10, which is apparently its hardcoded value.

This kb article describes changing the TcpMaxDataRetransmissions registry value for Windows 7, Windows 2008 R2, Windows 2008, and Windows Vista.

This 2015 post describes setting TcpMaxDataRetransmissions registry value as a troubleshooting measure.

Monday, January 9, 2017

When worlds collide! Quickstats, Filtered Indexes, Clustered ColumnStore Indexes and Access Violations


January 10, 2017 is T-SQL Tuesday!  Yahoo!!  Brent Ozar is hosting this month.

Here was the announce...

Announcing T-SQL Tuesday #86: SQL Server Bugs & Enhancement Requests
https://www.brentozar.com/archive/2017/01/announcing-t-sql-tuesday-87-sql-server-bugs-enhancement-requests/

And here's my contribution.

The T-SQL Tuesday announcement mentions Connect items marked as "Won't fix", so I hope I'm not coloring too far outside the lines.  This is a blog post about a Connect item that was fixed (off-label though), and how it ties into the intersection of ascending keys, clustered columnstore, and filtered indexes.

Here's the Connect Item involved - written by Michael Swart.

Trace flag 2390 can cause large compile time when dealing with filtered indexes. (Active)
https://connect.microsoft.com/SQLServer/feedback/details/2528743/

Huh.  "What does that have to do with clustered columnstore indexes?" you might ask.  No, really, it'd be a personal favor if you *did* ask...

Clustered columnstore indexes are pretty cool - and each major version of SQL Server since their introduction has lead to added features and more robustness.

Early in testing with clustered columnstore, there was an interesting bug fixed by kb3189645 - details at the link.

FIX: Access violation when you run a query that uses clustered columnstore index with trace flag 2389, 2390, or 4139
https://support.microsoft.com/en-us/kb/3189645

Let's reproduce this access violation on an exposed version.

It's important to know that async auto-stats updates are not enabled in this database.  When testing stats update behavior, having async enabled can make things confusing. The version for today's work is...











Access Violation with a Clustered Columnstore Index

The numbers function from Itzik Ben-Gan is the start of the fun, again.

SET NOCOUNT ON;
GO
CREATE FUNCTION dbo.GetNums(@low AS BIGINT, @high AS BIGINT) RETURNS TABLE
AS
RETURN
  WITH
    L0   AS (SELECT c FROM (SELECT 1 UNION ALL SELECT 1) AS D(c)),
    L1   AS (SELECT 1 AS c FROM L0 AS A CROSS JOIN L0 AS B),
    L2   AS (SELECT 1 AS c FROM L1 AS A CROSS JOIN L1 AS B),
    L3   AS (SELECT 1 AS c FROM L2 AS A CROSS JOIN L2 AS B),
    L4   AS (SELECT 1 AS c FROM L3 AS A CROSS JOIN L3 AS B),
    L5   AS (SELECT 1 AS c FROM L4 AS A CROSS JOIN L4 AS B),
    Nums AS (SELECT ROW_NUMBER() OVER(ORDER BY (SELECT NULL)) AS rownum
             FROM L5)
  SELECT TOP(@high - @low + 1) @low + rownum - 1 AS n
  FROM Nums
  ORDER BY rownum;
----------------------------------------------------------------------
-- © Itzik Ben-Gan
----------------------------------------------------------------------
/* http://tsql.solidq.com/SourceCodes/GetNums.txt */
GO

Lets create a single-column rowstore table for the test. We'll also create statistics on that single column. Manually-created or auto-generated stats work in this role. Avoiding the auto-generated name makes it look just a little cleaner, maybe.

IF OBJECT_ID('test_histogram_amendments') IS NOT NULL 
  DROP TABLE test_histogram_amendments;
CREATE TABLE test_histogram_amendments(col1 BIGINT);
CREATE STATISTICS stats_col1 ON test_histogram_amendments(col1);

Let's add a million rows, and update stats.

INSERT INTO dbo.test_histogram_amendments
SELECT TOP (1000000) nums.n
FROM dbo.getNums(1, 1000000) nums;
UPDATE STATISTICS test_histogram_amendments;

Lets check on the stats.

SELECT st.name AS table_name, ss.name AS sts_name, 
       sp.last_updated, sp.rows, sp.unfiltered_rows, 
    sp.rows_sampled, sp.steps, sp.modification_counter
FROM sys.stats ss
JOIN sys.tables st ON ss.object_id = st.object_id 
CROSS APPLY sys.dm_db_stats_properties(ss.object_id,ss.stats_id) sp
WHERE st.name = 'test_histogram_amendments';

Stats are there - sampled, with just over 500000 values sampled.









Let's convert the rowstore table to a clustered columnstore index, and insert 1000 more consecutive integers.

CREATE CLUSTERED COLUMNSTORE INDEX CCI_test_histogram_amendments 
ON test_histogram_amendments;

INSERT INTO dbo.test_histogram_amendments
SELECT TOP (1000) nums.n
FROM dbo.getNums(1000001, 1001000) nums;

Column Col1 hasn't been updated enough times to be branded as an ascending key.  No worries.  Trace flag 2390 uses quickstats queries for stats keys of type 'Unknown', and trace flag 4139 will issue a quickstats query for stats keys of type 'Ascending', 'Unknown', or 'Stationary'.  The quickstats queries are only used when the optimizer deems necessary for a range outside the histogram.

So what happens with the following query?


SELECT COUNT(*) FROM test_histogram_amendments WHERE COL1 > 1000000 AND COL1 < 2000000
OPTION (QUERYTRACEON 4139);











That doesn't look so nice.

It isn't so nice.

Stack dump.


Date,Source,Severity,Message
01/09/2017 13:31:48,Server,Unknown,A user request from the session with SPID 54 generated a fatal exception. SQL Server is terminating this session. Contact Product Support Services with the dump produced in the log directory.
01/09/2017 13:31:48,Server,Unknown,Error: 17310 Severity: 20 State: 1.
01/09/2017 13:31:48,spid54,Unknown,External dump process return code 0x20000001.External dump process returned no errors.
01/09/2017 13:31:48,spid54,Unknown,[INFO]          Identity             Begin               End |        State                  Result     Error  Speculate   Prepared LazyCommit   ReadOnly |      Transaction         Database          ThreadId |   ReadSet  WriteSet   ScanSet Savepoint LogSizeRq | CommitDep TotalComm       Dependent 0       Dependent 1       Dependent 2       Dependent 3       Dependent 4       Dependent 5       Dependent 6       Dependent 7 |            Area  Location |
01/09/2017 13:31:48,spid54,Unknown,Stack Signature for the dump is 0x000000016573B630
01/09/2017 13:31:48,spid54,Unknown,00007FFD84C254E4 Module(ntdll+00000000000154E4)
01/09/2017 13:31:48,spid54,Unknown,00007FFD846613D2 Module(KERNEL32+00000000000013D2)
01/09/2017 13:31:48,spid54,Unknown,00007FFD755ACC68 Module(sqldk+000000000002CC68)
01/09/2017 13:31:48,spid54,Unknown,00007FFD755AC3D9 Module(sqldk+000000000002C3D9)
01/09/2017 13:31:48,spid54,Unknown,00007FFD755AC450 Module(sqldk+000000000002C450)
01/09/2017 13:31:48,spid54,Unknown,00007FFD755AC2FF Module(sqldk+000000000002C2FF)
01/09/2017 13:31:48,spid54,Unknown,00007FFD75584306 Module(sqldk+0000000000004306)
01/09/2017 13:31:48,spid54,Unknown,00007FFD75584634 Module(sqldk+0000000000004634)
01/09/2017 13:31:48,spid54,Unknown,00007FFD75584850 Module(sqldk+0000000000004850)
01/09/2017 13:31:48,spid54,Unknown,00007FFD76302733 Module(sqllang+0000000000012733)
01/09/2017 13:31:48,spid54,Unknown,00007FFD76302617 Module(sqllang+0000000000012617)
01/09/2017 13:31:48,spid54,Unknown,00007FFD762FC1C1 Module(sqllang+000000000000C1C1)
01/09/2017 13:31:48,spid54,Unknown,00007FFD7636C917 Module(sqllang+000000000007C917)
01/09/2017 13:31:48,spid54,Unknown,00007FFD7636C9BF Module(sqllang+000000000007C9BF)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763B03D0 Module(sqllang+00000000000C03D0)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763B01D9 Module(sqllang+00000000000C01D9)
01/09/2017 13:31:48,spid54,Unknown,00007FFD76F4029F Module(sqllang+0000000000C5029F)
01/09/2017 13:31:48,spid54,Unknown,00007FFD76F10246 Module(sqllang+0000000000C20246)
01/09/2017 13:31:48,spid54,Unknown,00007FFD7636C917 Module(sqllang+000000000007C917)
01/09/2017 13:31:48,spid54,Unknown,00007FFD7636C9BF Module(sqllang+000000000007C9BF)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763B03D0 Module(sqllang+00000000000C03D0)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763B01D9 Module(sqllang+00000000000C01D9)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763D05F9 Module(sqllang+00000000000E05F9)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763B6F14 Module(sqllang+00000000000C6F14)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763B9CCA Module(sqllang+00000000000C9CCA)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763B9F00 Module(sqllang+00000000000C9F00)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763EC6BA Module(sqllang+00000000000FC6BA)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763EC9D0 Module(sqllang+00000000000FC9D0)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763FB2F5 Module(sqllang+000000000010B2F5)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763FB2F5 Module(sqllang+000000000010B2F5)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763EB6E6 Module(sqllang+00000000000FB6E6)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763EB85E Module(sqllang+00000000000FB85E)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763B73E2 Module(sqllang+00000000000C73E2)
01/09/2017 13:31:48,spid54,Unknown,00007FFD763C297E Module(sqllang+00000000000D297E)
01/09/2017 13:31:48,spid54,Unknown,00007FFD7640AA40 Module(sqllang+000000000011AA40)
01/09/2017 13:31:48,spid54,Unknown,00007FFD76409BF6 Module(sqllang+0000000000119BF6)
01/09/2017 13:31:48,spid54,Unknown,00007FFD76409114 Module(sqllang+0000000000119114)
01/09/2017 13:31:48,spid54,Unknown,00007FFD766E4E6E Module(sqllang+00000000003F4E6E)
01/09/2017 13:31:48,spid54,Unknown,00007FFD773AA442 Module(sqllang+00000000010BA442)
01/09/2017 13:31:48,spid54,Unknown,00007FFD773CA6A6 Module(sqllang+00000000010DA6A6)
01/09/2017 13:31:48,spid54,Unknown,* Short Stack Dump
01/09/2017 13:31:48,spid54,Unknown,* -------------------------------------------------------------------------------
01/09/2017 13:31:48,spid54,Unknown,* *******************************************************************************
01/09/2017 13:31:48,spid54,Unknown,*        Rip: 00007FFD773CA6A6:  C0FF491374193B48  BA7CC33B4DC1FF41  C308245C8B48C032  C301B008245C8B48  9090909090909090  0000D8918B489090
01/09/2017 13:31:48,spid54,Unknown,*        R15: 000000002C61EAB0:  412E8C5000000000  0000000000000000  0000000000000001  0000000000000001  0000000A7F4EA280  0000000849F9D530
01/09/2017 13:31:48,spid54,Unknown,*        R14: 0000000849F9C040:  00007FFD756EF2C0  0000000800000001  0000000000002000  000000000000006D  00000008B7A83140  0000000000000000
01/09/2017 13:31:48,spid54,Unknown,*        R13: 0000000000000001:
01/09/2017 13:31:48,spid54,Unknown,*        R12: 0000000849F9C040:  00007FFD756EF2C0  0000000800000001  0000000000002000  000000000000006D  00000008B7A83140  0000000000000000
01/09/2017 13:31:48,spid54,Unknown,*        R11: 0000000000000001:
01/09/2017 13:31:48,spid54,Unknown,*        R10: 0000000849F94310:  00007FFD77B363E0  0000000000000002  00007FFD77BEBF58  000000000000002F  0000000849F9C040  0000000849F97220
01/09/2017 13:31:48,spid54,Unknown,*         R9: 0000000000000000:
01/09/2017 13:31:48,spid54,Unknown,*         R8: 0000000000000000:
01/09/2017 13:31:48,spid54,Unknown,*        Rdi: 0000000849FAB100:  00007FFD77B61BB0  0000000000000001  0000000849F9C040  0000003E0000003E  FFFFFFFFFFFFFFFF  0000000000350008
01/09/2017 13:31:48,spid54,Unknown,*        Rsi: 0000000849F9EF40:  00007FFD77BF44C0  0000001D00000002  0000000849FA0410  0000000849F94310  0000000000000000  0000007F0000007F
01/09/2017 13:31:48,spid54,Unknown,*        Rbp: 000000002C61E800:  FFFFFFFFFFFFFFFF  FFFFFFFFFFFFFFFE  0000000849FAB118  00007FFD7640169C  412E848000000000  0000000000000000
01/09/2017 13:31:48,spid54,Unknown,*        Rsp: 000000002C61E6F8:  00007FFD773AA442  0000000849F9D530  000000002C61E938  000000002C61E858  000000002C61E8F8  0000000000000000
01/09/2017 13:31:48,spid54,Unknown,*        Rbx: 0000000849F9EF40:  00007FFD77BF44C0  0000001D00000002  0000000849FA0410  0000000849F94310  0000000000000000  0000007F0000007F
01/09/2017 13:31:48,spid54,Unknown,*        Rdx: 0000000000000001:
01/09/2017 13:31:48,spid54,Unknown,*        Rcx: 0000000000000000:
01/09/2017 13:31:48,spid54,Unknown,*        Rax: 0000000849F9E660:  0000000849F9C040  0000000000000001  0000000000000004  0000000000000000  00007FFD77B342E0  0000000000000001
01/09/2017 13:31:48,spid54,Unknown,*     EFlags: 0000000000010246:
01/09/2017 13:31:48,spid54,Unknown,*      SegSs: 000000000000002B:
01/09/2017 13:31:48,spid54,Unknown,*      SegGs: 000000000000002B:
01/09/2017 13:31:48,spid54,Unknown,*      SegFs: 0000000000000053:
01/09/2017 13:31:48,spid54,Unknown,*      SegEs: 000000000000002B:
01/09/2017 13:31:48,spid54,Unknown,*      SegDs: 000000000000002B:
01/09/2017 13:31:48,spid54,Unknown,*      SegCs: 0000000000000033:
01/09/2017 13:31:48,spid54,Unknown,*      MxCsr: 0000000000001FA8:
01/09/2017 13:31:48,spid54,Unknown,* ContextFlags: 000000000010005F:
01/09/2017 13:31:48,spid54,Unknown,*     P6Home: 0000000000002000:
01/09/2017 13:31:48,spid54,Unknown,*     P5Home: 0000000000000003:
01/09/2017 13:31:48,spid54,Unknown,*     P4Home: 0000000000000002:
01/09/2017 13:31:48,spid54,Unknown,*     P3Home: 0000000849F9EF40:  00007FFD77BF44C0  0000001D00000002  0000000849FA0410  0000000849F94310  0000000000000000  0000007F0000007F
01/09/2017 13:31:48,spid54,Unknown,*     P2Home: 00007FFD755A2DB2:  2474C08548D88B4C  F0FFFFFFF8C1C748  408B48604BC10F48  245C8B481F894C10  834840246C8B4838  24748948C35F20C4
01/09/2017 13:31:48,spid54,Unknown,*     P1Home: 00000000257E9710:  0000000000000000  0000000000000000  000000000201EFA0  000000000201EFA0  0000000849F80000  0000000849FB6000
01/09/2017 13:31:48,spid54,Unknown,*
01/09/2017 13:31:48,spid54,Unknown,* dbghelp                        00000000570A0000  0000000057235FFF  00196000
01/09/2017 13:31:48,spid54,Unknown,* apphelp                        00007FFD805C0000  00007FFD8064DFFF  0008e000
01/09/2017 13:31:48,spid54,Unknown,* ESENT                          00007FFD7D0F0000  00007FFD7D3B9FFF  002ca000
01/09/2017 13:31:48,spid54,Unknown,* ualapi                         00007FFD7D530000  00007FFD7D548FFF  00019000
01/09/2017 13:31:48,spid54,Unknown,* msxml3                         00007FFD6E6F0000  00007FFD6E930FFF  00241000
01/09/2017 13:31:48,spid54,Unknown,* xpstar                         00007FFD6E950000  00007FFD6E95CFFF  0000d000
01/09/2017 13:31:48,spid54,Unknown,* SQLSCM                         00007FFD72180000  00007FFD7218EFFF  0000f000
01/09/2017 13:31:48,spid54,Unknown,* ODBC32                         00007FFD72200000  00007FFD722C1FFF  000c2000
01/09/2017 13:31:48,spid54,Unknown,* xpstar                         00007FFD6E960000  00007FFD6E9C7FFF  00068000
01/09/2017 13:31:48,spid54,Unknown,* xpsqlbot                       00007FFD6E9D0000  00007FFD6E9D7FFF  00008000
01/09/2017 13:31:48,spid54,Unknown,* loadperf                       00007FFD6EA20000  00007FFD6EA43FFF  00024000
01/09/2017 13:31:48,spid54,Unknown,* wbemcomn                       00007FFD750F0000  00007FFD75171FFF  00082000
01/09/2017 13:31:48,spid54,Unknown,* wmiaprpl                       00007FFD6EA50000  00007FFD6EA75FFF  00026000
01/09/2017 13:31:48,spid54,Unknown,* usbperf                        00007FFD6EA80000  00007FFD6EA87FFF  00008000
01/09/2017 13:31:48,spid54,Unknown,* SETUPAPI                       00007FFD84A30000  00007FFD84C09FFF  001da000
01/09/2017 13:31:48,spid54,Unknown,* UTILDLL                        00007FFD6EA90000  00007FFD6EAA6FFF  00017000
01/09/2017 13:31:48,spid54,Unknown,* WINSTA                         00007FFD81C40000  00007FFD81C99FFF  0005a000
01/09/2017 13:31:48,spid54,Unknown,* perfts                         00007FFD6EAB0000  00007FFD6EAB8FFF  00009000
01/09/2017 13:31:48,spid54,Unknown,* Perfctrs                       00007FFD6EAC0000  00007FFD6EAD0FFF  00011000
01/09/2017 13:31:48,spid54,Unknown,* tapiperf                       00007FFD6ED50000  00007FFD6ED57FFF  00008000
01/09/2017 13:31:48,spid54,Unknown,* perf-MSSQL12.MSSQLSERVER-sqlagtctr 00000000574E0000  00000000574FBFFF  0001c000
01/09/2017 13:31:48,spid54,Unknown,* DSROLE                         00007FFD7F9F0000  00007FFD7F9F9FFF  0000a000
01/09/2017 13:31:48,spid54,Unknown,* clrjit                         00007FFD6F520000  00007FFD6F64DFFF  0012e000
01/09/2017 13:31:48,spid54,Unknown,* SqlAccess                      0000000001580000  00000000015F1FFF  00072000
01/09/2017 13:31:48,spid54,Unknown,* ncryptsslp                     00007FFD7CBD0000  00007FFD7CBECFFF  0001d000
01/09/2017 13:31:48,spid54,Unknown,* winspool                       00007FFD72020000  00007FFD720A1FFF  00082000
01/09/2017 13:31:48,spid54,Unknown,* rasman                         00007FFD7DD50000  00007FFD7DD7FFFF  00030000
01/09/2017 13:31:48,spid54,Unknown,* rasctrs                        00007FFD720B0000  00007FFD720B8FFF  00009000
01/09/2017 13:31:48,spid54,Unknown,* perfproc                       00007FFD720C0000  00007FFD720CEFFF  0000f000
01/09/2017 13:31:48,spid54,Unknown,* perfos                         00007FFD720D0000  00007FFD720DCFFF  0000d000
01/09/2017 13:31:48,spid54,Unknown,* BROWCLI                        00007FFD720E0000  00007FFD720F2FFF  00013000
01/09/2017 13:31:48,spid54,Unknown,* perfnet                        00007FFD72100000  00007FFD72109FFF  0000a000
01/09/2017 13:31:48,spid54,Unknown,* WMICLNT                        00007FFD7F420000  00007FFD7F42EFFF  0000f000
01/09/2017 13:31:48,spid54,Unknown,* perfdisk                       00007FFD72110000  00007FFD7211EFFF  0000f000
01/09/2017 13:31:48,spid54,Unknown,* mscorlib.ni                    00007FFD70890000  00007FFD71E31FFF  015a2000
01/09/2017 13:31:48,spid54,Unknown,* perf-MSSQLSERVER-sqlctr12.0.2000.8 00007FFD72120000  00007FFD72172FFF  00053000
01/09/2017 13:31:48,spid54,Unknown,* ktmw32                         00007FFD7E4E0000  00007FFD7E4EAFFF  0000b000
01/09/2017 13:31:48,spid54,Unknown,* MTXCLU                         00007FFD72190000  00007FFD721F6FFF  00067000
01/09/2017 13:31:48,spid54,Unknown,* MSDTCPRX                       00007FFD722D0000  00007FFD723ACFFF  000dd000
01/09/2017 13:31:48,spid54,Unknown,* ATL                            00007FFD7F880000  00007FFD7F89FFFF  00020000
01/09/2017 13:31:48,spid54,Unknown,* msdtcuiu                       00007FFD723B0000  00007FFD723FFFFF  00050000
01/09/2017 13:31:48,spid54,Unknown,* fwpuclnt                       00007FFD7EF60000  00007FFD7EFCAFFF  0006b000
01/09/2017 13:31:48,spid54,Unknown,* WINNSI                         00007FFD7F440000  00007FFD7F449FFF  0000a000
01/09/2017 13:31:48,spid54,Unknown,* IPHLPAPI                       00007FFD7F8A0000  00007FFD7F8C9FFF  0002a000
01/09/2017 13:31:48,spid54,Unknown,* rasadhlp                       00007FFD7D560000  00007FFD7D569FFF  0000a000
01/09/2017 13:31:48,spid54,Unknown,* DNSAPI                         00007FFD81350000  00007FFD813F3FFF  000a4000
01/09/2017 13:31:48,spid54,Unknown,* DSPARSE                        00007FFD7D520000  00007FFD7D52CFFF  0000d000
01/09/2017 13:31:48,spid54,Unknown,* ntdsapi                        00007FFD7FA20000  00007FFD7FA48FFF  00029000
01/09/2017 13:31:48,spid54,Unknown,* ntmarta                        00007FFD7DC40000  00007FFD7DC71FFF  00032000
01/09/2017 13:31:48,spid54,Unknown,* mswsock                        00007FFD81560000  00007FFD815B8FFF  00059000
01/09/2017 13:31:48,spid54,Unknown,* esentprf                       00007FFD72400000  00007FFD72417FFF  00018000
01/09/2017 13:31:48,spid54,Unknown,* MSVCR80                        0000000057570000  0000000057638FFF  000c9000
01/09/2017 13:31:48,spid54,Unknown,* aspnet_perf                    00007FFD72420000  00007FFD7242CFFF  0000d000
01/09/2017 13:31:48,spid54,Unknown,* aspnet_perf                    00007FFD73C80000  00007FFD73C8CFFF  0000d000
01/09/2017 13:31:48,spid54,Unknown,* aspnet_counters                00007FFD73C90000  00007FFD73C97FFF  00008000
01/09/2017 13:31:48,spid54,Unknown,* WTSAPI32                       00007FFD7EEE0000  00007FFD7EEF1FFF  00012000
01/09/2017 13:31:48,spid54,Unknown,* CorperfmonExt                  00007FFD72430000  00007FFD72455FFF  00026000
01/09/2017 13:31:48,spid54,Unknown,* perfcounter                    00007FFD72460000  00007FFD7249CFFF  0003d000
01/09/2017 13:31:48,spid54,Unknown,* netfxperf                      00007FFD73CA0000  00007FFD73CAEFFF  0000f000
01/09/2017 13:31:48,spid54,Unknown,* MSVCR120_CLR0400               00007FFD71E40000  00007FFD71F15FFF  000d6000
01/09/2017 13:31:48,spid54,Unknown,* clr                            00007FFD724A0000  00007FFD72E3EFFF  0099f000
01/09/2017 13:31:48,spid54,Unknown,* netbios                        00007FFD750E0000  00007FFD750EAFFF  0000b000
01/09/2017 13:31:48,spid54,Unknown,* BatchParser                    00007FFD7C4F0000  00007FFD7C517FFF  00028000
01/09/2017 13:31:48,spid54,Unknown,* DPAPI                          00007FFD809F0000  00007FFD809F9FFF  0000a000
01/09/2017 13:31:48,spid54,Unknown,* SQLNCLIR11                     0000000057640000  0000000057677FFF  00038000
01/09/2017 13:31:48,spid54,Unknown,* SHCORE                         00007FFD80650000  00007FFD80701FFF  000b2000
01/09/2017 13:31:48,spid54,Unknown,* SHELL32                        00007FFD82F90000  00007FFD844B7FFF  01528000
01/09/2017 13:31:48,spid54,Unknown,* COMDLG32                       00007FFD825A0000  00007FFD82655FFF  000b6000
01/09/2017 13:31:48,spid54,Unknown,* COMCTL32                       00007FFD7C790000  00007FFD7C833FFF  000a4000
01/09/2017 13:31:48,spid54,Unknown,* sqlncli11                      00007FFD72E40000  00007FFD73192FFF  00353000
01/09/2017 13:31:48,spid54,Unknown,* clbcatq                        00007FFD82670000  00007FFD82725FFF  000b6000
01/09/2017 13:31:48,spid54,Unknown,* kernel.appcore                 00007FFD80A00000  00007FFD80A0AFFF  0000b000
01/09/2017 13:31:48,spid54,Unknown,* security                       00007FFD7CE40000  00007FFD7CE42FFF  00003000
01/09/2017 13:31:48,spid54,Unknown,* mscoreei                       00007FFD731E0000  00007FFD7327CFFF  0009d000
01/09/2017 13:31:48,spid54,Unknown,* MSCOREE                        00007FFD7C8C0000  00007FFD7C923FFF  00064000
01/09/2017 13:31:48,spid54,Unknown,* schannel                       00007FFD810E0000  00007FFD8114DFFF  0006e000
01/09/2017 13:31:48,spid54,Unknown,* kerberos                       00007FFD815C0000  00007FFD816B7FFF  000f8000
01/09/2017 13:31:48,spid54,Unknown,* msv1_0                         00007FFD81400000  00007FFD8146DFFF  0006e000
01/09/2017 13:31:48,spid54,Unknown,* pcwum                          00007FFD812E0000  00007FFD812EDFFF  0000e000
01/09/2017 13:31:48,spid54,Unknown,* SHLWAPI                        00007FFD82AF0000  00007FFD82B43FFF  00054000
01/09/2017 13:31:48,spid54,Unknown,* XmlLite                        00007FFD7E4A0000  00007FFD7E4D8FFF  00039000
01/09/2017 13:31:48,spid54,Unknown,* dbghelp                        0000000057680000  0000000057815FFF  00196000
01/09/2017 13:31:48,spid54,Unknown,* hkengine                       00007FFD7C930000  00007FFD7CADEFFF  001af000
01/09/2017 13:31:48,spid54,Unknown,* hkcompile                      00007FFD7CAE0000  00007FFD7CB9DFFF  000be000
01/09/2017 13:31:48,spid54,Unknown,* hkruntime                      00007FFD73930000  00007FFD73BE6FFF  002b7000
01/09/2017 13:31:48,spid54,Unknown,* VERSION                        00007FFD7CC50000  00007FFD7CC59FFF  0000a000
01/09/2017 13:31:48,spid54,Unknown,* RESUTILS                       00007FFD740A0000  00007FFD740EBFFF  0004c000
01/09/2017 13:31:48,spid54,Unknown,* cryptdll                       00007FFD816F0000  00007FFD81709FFF  0001a000
01/09/2017 13:31:48,spid54,Unknown,* CLUSAPI                        00007FFD74030000  00007FFD7409DFFF  0006e000
01/09/2017 13:31:48,spid54,Unknown,* gpapi                          00007FFD80F50000  00007FFD80F73FFF  00024000
01/09/2017 13:31:48,spid54,Unknown,* NTASN1                         00007FFD817B0000  00007FFD817E6FFF  00037000
01/09/2017 13:31:48,spid54,Unknown,* ncrypt                         00007FFD817F0000  00007FFD81814FFF  00025000
01/09/2017 13:31:48,spid54,Unknown,* imagehlp                       00007FFD84600000  00007FFD84615FFF  00016000
01/09/2017 13:31:48,spid54,Unknown,* bcrypt                         00007FFD81820000  00007FFD81845FFF  00026000
01/09/2017 13:31:48,spid54,Unknown,* rsaenh                         00007FFD81150000  00007FFD81185FFF  00036000
01/09/2017 13:31:48,spid54,Unknown,* CRYPTSP                        00007FFD816D0000  00007FFD816EFFFF  00020000
01/09/2017 13:31:48,spid54,Unknown,* sqlevn70                       00007FFD74630000  00007FFD748DDFFF  002ae000
01/09/2017 13:31:48,spid54,Unknown,* cscapi                         00007FFD7C760000  00007FFD7C771FFF  00012000
01/09/2017 13:31:48,spid54,Unknown,* instapi120                     00007FFD75060000  00007FFD7506EFFF  0000f000
01/09/2017 13:31:48,spid54,Unknown,* bcryptPrimitives               00007FFD81B30000  00007FFD81B92FFF  00063000
01/09/2017 13:31:48,spid54,Unknown,* CRYPTBASE                      00007FFD81CA0000  00007FFD81CAAFFF  0000b000
01/09/2017 13:31:48,spid54,Unknown,* SAMCLI                         00007FFD7C690000  00007FFD7C6A6FFF  00017000
01/09/2017 13:31:48,spid54,Unknown,* DEVOBJ                         00007FFD80BE0000  00007FFD80C07FFF  00028000
01/09/2017 13:31:48,spid54,Unknown,* cfgmgr32                       00007FFD81FE0000  00007FFD8202EFFF  0004f000
01/09/2017 13:31:48,spid54,Unknown,* LOGONCLI                       00007FFD81310000  00007FFD8134EFFF  0003f000
01/09/2017 13:31:48,spid54,Unknown,* WINMMBASE                      00007FFD751C0000  00007FFD751E9FFF  0002a000
01/09/2017 13:31:48,spid54,Unknown,* profapi                        00007FFD81CE0000  00007FFD81CF4FFF  00015000
01/09/2017 13:31:48,spid54,Unknown,* GDI32                          00007FFD82290000  00007FFD823DEFFF  0014f000
01/09/2017 13:31:48,spid54,Unknown,* combase                        00007FFD847A0000  00007FFD849B0FFF  00211000
01/09/2017 13:31:48,spid54,Unknown,* NSI                            00007FFD84520000  00007FFD84528FFF  00009000
01/09/2017 13:31:48,spid54,Unknown,* MSASN1                         00007FFD81DE0000  00007FFD81DF0FFF  00011000
01/09/2017 13:31:48,spid54,Unknown,* SspiCli                        00007FFD82260000  00007FFD8228DFFF  0002e000
01/09/2017 13:31:48,spid54,Unknown,* WINMM                          00007FFD751F0000  00007FFD75211FFF  00022000
01/09/2017 13:31:48,spid54,Unknown,* WINTRUST                       00007FFD82030000  00007FFD82080FFF  00051000
01/09/2017 13:31:48,spid54,Unknown,* AUTHZ                          00007FFD80FB0000  00007FFD80FF7FFF  00048000
01/09/2017 13:31:48,spid54,Unknown,* USERENV                        00007FFD812B0000  00007FFD812D0FFF  00021000
01/09/2017 13:31:48,spid54,Unknown,* qds                            00007FFD75220000  00007FFD752ADFFF  0008e000
01/09/2017 13:31:48,spid54,Unknown,* OLEAUT32                       00007FFD84530000  00007FFD845F5FFF  000c6000
01/09/2017 13:31:48,spid54,Unknown,* ole32                          00007FFD82DF0000  00007FFD82F83FFF  00194000
01/09/2017 13:31:48,spid54,Unknown,* USER32                         00007FFD82970000  00007FFD82AE6FFF  00177000
01/09/2017 13:31:48,spid54,Unknown,* WINHTTP                        00007FFD78570000  00007FFD78636FFF  000c7000
01/09/2017 13:31:48,spid54,Unknown,* WS2_32                         00007FFD828B0000  00007FFD82909FFF  0005a000
01/09/2017 13:31:48,spid54,Unknown,* PSAPI                          00007FFD82890000  00007FFD82896FFF  00007000
01/09/2017 13:31:48,spid54,Unknown,* Secur32                        00007FFD7D580000  00007FFD7D58BFFF  0000c000
01/09/2017 13:31:48,spid54,Unknown,* CRYPT32                        00007FFD81E00000  00007FFD81FDEFFF  001df000
01/09/2017 13:31:48,spid54,Unknown,* sechost                        00007FFD82910000  00007FFD82968FFF  00059000
01/09/2017 13:31:48,spid54,Unknown,* RPCRT4                         00007FFD82B50000  00007FFD82C8FFFF  00140000
01/09/2017 13:31:48,spid54,Unknown,* msvcrt                         00007FFD82C90000  00007FFD82D39FFF  000aa000
01/09/2017 13:31:48,spid54,Unknown,* wkscli                         00007FFD809D0000  00007FFD809E6FFF  00017000
01/09/2017 13:31:48,spid54,Unknown,* srvcli                         00007FFD81940000  00007FFD81965FFF  00026000
01/09/2017 13:31:48,spid54,Unknown,* netutils                       00007FFD80710000  00007FFD8071BFFF  0000c000
01/09/2017 13:31:48,spid54,Unknown,* sqldk                          00007FFD75580000  00007FFD75A4CFFF  004cd000
01/09/2017 13:31:48,spid54,Unknown,* sqlTsEs                        00007FFD75A50000  00007FFD762E3FFF  00894000
01/09/2017 13:31:48,spid54,Unknown,* sqllang                        00007FFD762F0000  00007FFD7856FFFF  02280000
01/09/2017 13:31:48,spid54,Unknown,* sqlmin                         00007FFD78640000  00007FFD7C4EDFFF  03eae000
01/09/2017 13:31:48,spid54,Unknown,* SQLOS                          00007FFD7C750000  00007FFD7C756FFF  00007000
01/09/2017 13:31:48,spid54,Unknown,* MSVCP100                       00000000579B0000  0000000057A47FFF  00098000
01/09/2017 13:31:48,spid54,Unknown,* MSVCR100                       0000000057A50000  0000000057B21FFF  000d2000
01/09/2017 13:31:48,spid54,Unknown,* ADVAPI32                       00007FFD82D40000  00007FFD82DE9FFF  000aa000
01/09/2017 13:31:48,spid54,Unknown,* opends60                       00007FFD7C780000  00007FFD7C788FFF  00009000
01/09/2017 13:31:48,spid54,Unknown,* pdh                            00007FFD7C640000  00007FFD7C68EFFF  0004f000
01/09/2017 13:31:48,spid54,Unknown,* NETAPI32                       00007FFD7FA00000  00007FFD7FA15FFF  00016000
01/09/2017 13:31:48,spid54,Unknown,* KERNELBASE                     00007FFD82140000  00007FFD82254FFF  00115000
01/09/2017 13:31:48,spid54,Unknown,* KERNEL32                       00007FFD84660000  00007FFD8479DFFF  0013e000
01/09/2017 13:31:48,spid54,Unknown,* ntdll                          00007FFD84C10000  00007FFD84DBCFFF  001ad000
01/09/2017 13:31:48,spid54,Unknown,* sqlservr                       00007FF7A12C0000  00007FF7A131FFFF  00060000
01/09/2017 13:31:48,spid54,Unknown,*  MODULE                          BASE      END       SIZE
01/09/2017 13:31:48,spid54,Unknown,*
01/09/2017 13:31:48,spid54,Unknown,*
01/09/2017 13:31:48,spid54,Unknown,*  000000 AND COL1 < 2000000
01/09/2017 13:31:48,spid54,Unknown,*             SELECT COUNT(*) FROM test_histogram_amendments WHERE COL1 > 1
01/09/2017 13:31:48,spid54,Unknown,* Input Buffer 194 bytes -
01/09/2017 13:31:48,spid54,Unknown,*   Access Violation occurred reading address 0000000000000000
01/09/2017 13:31:48,spid54,Unknown,*   Exception Code    = c0000005 EXCEPTION_ACCESS_VIOLATION
01/09/2017 13:31:48,spid54,Unknown,*   Exception Address = 00007FFD773CA6A6 Module(sqllang+00000000010DA6A6)
01/09/2017 13:31:48,spid54,Unknown,*
01/09/2017 13:31:48,spid54,Unknown,*
01/09/2017 13:31:48,spid54,Unknown,*   01/09/17 13:31:48 spid 54
01/09/2017 13:31:48,spid54,Unknown,* BEGIN STACK DUMP:
01/09/2017 13:31:48,spid54,Unknown,*
01/09/2017 13:31:48,spid54,Unknown,* *******************************************************************************
01/09/2017 13:31:48,spid54,Unknown,SqlDumpExceptionHandler: Process 54 generated fatal exception c0000005 EXCEPTION_ACCESS_VIOLATION. SQL Server is terminating this process.
01/09/2017 13:31:48,spid54,Unknown,***Stack Dump being sent to C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\LOG\SQLDump0011.txt


An access violation occurs in the quickstats query codepath when used in the context of a clustered columnstore index.  Quickstats queries are used to amend the histogram if there have been modifications outside the current stats histogram and the query optimizer is interested in the range beyond the histogram.

The access violation occurs even when simply retrieving an estimated plan in SSMS, if the optimizer decides to issue a quickstats query.

What about a rowstore table with a nonclustered index?

With that in mind, let's alter the test a little.  Let's create the rowstore table, adding just a nonclustered index on Col1. We'll insert 1000000 rows, update statistics, then add 1000 rows without updating statistics.

IF OBJECT_ID('test_histogram_amendments') IS NOT NULL DROP TABLE test_histogram_amendments;
CREATE TABLE test_histogram_amendments(col1 BIGINT);
CREATE NONCLUSTERED INDEX nci_col1 ON test_histogram_amendments(col1);

INSERT INTO dbo.test_histogram_amendments
SELECT TOP (1000000) nums.n
FROM dbo.getNums(1, 1000000) nums;
UPDATE STATISTICS test_histogram_amendments;
  
INSERT INTO dbo.test_histogram_amendments
SELECT TOP (1000) nums.n
FROM dbo.getNums(1000001, 1001000) nums;

Let's use an Extended Events Session to capture the quickstats query.

DECLARE @sqlText1 NVARCHAR(1024) = N'CREATE EVENT SESSION track_sql_text_spid_' 
+ CONVERT(NVARCHAR(256),@@SPID) 
  +' ON SERVER 
  ADD EVENT sqlserver.sp_statement_completed(
      ACTION(sqlserver.sql_text)
      WHERE ([sqlserver].[session_id]=(' + CONVERT(NVARCHAR(256), @@SPID) +')))
  ADD TARGET package0.ring_buffer
  WITH (MAX_DISPATCH_LATENCY = 1 SECONDS);
  ALTER EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256), @@SPID) 
  +' ON SERVER 
  STATE = START;';
EXEC (@sqlText1);

Because we hope to capture the quickstats query at event sqlserver.sp_statement_completed, let's put the test query into a stored procedure.


CREATE PROCEDURE sp_test_histogram_amendments
AS 
SELECT COUNT(*) FROM test_histogram_amendments WHERE COL1 > 1000000 AND COL1 < 2000000
OPTION (QUERYTRACEON 4139);

Now let's execute the store procedure, to submit the test query.


EXEC sp_test_histogram_amendments;

Drop the event from the EE session.

DECLARE @sqlText2 NVARCHAR(1024) =
N'ALTER EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256), @@SPID) +' ON SERVER
DROP EVENT sqlserver.sp_statement_completed;'

EXEC (@sqlText2);

Now - what did we catch in our net?

DECLARE @sqlText3 NVARCHAR(1024) =
N'SELECT sql_text
FROM
(     SELECT
        tab.event.value(''(event/data[@name="statement"]/value)[1]'', ''nvarchar(max)'') as [sql_text]
      FROM
    (   SELECT n.query(''.'') as event
        FROM
        (
            SELECT CAST(target_data AS XML) AS target_xml
            FROM sys.dm_xe_sessions AS s   
            JOIN sys.dm_xe_session_targets AS t
                ON s.address = t.event_session_address
            WHERE s.name = ''track_sql_text_spid_' + CONVERT(NVARCHAR(256), @@SPID) +'''
               AND t.target_name = ''ring_buffer''
         ) AS sub
        CROSS APPLY target_xml.nodes(''RingBufferTarget/event'') AS q(n)
    ) AS tab
) tab2
WHERE tab2.sql_text LIKE ''%StatMan%'';';
EXEC (@sqlText3);

There it is - the quickstats query.  Not much to it.  Just find the max value of the lead column for the statistics on an ordered index.









Let's take a look at the plan for that inner query.
It's efficient - only needs to read one row from the nonclustered index to find the max value.


















Quickstats were first introduced along with trace flags 2389 and 2390 in SQL Server 2005 SP1; kb922063 followed shortly after.
FIX: You may notice a large increase in compile time when you enable trace flags 2389 and 2390 in SQL Server 2005 Service Pack 1
https://support.microsoft.com/en-us/kb/922063

Unless there was an ordered index with the column as the lead column, finding the maximum value would require a full scan.  Kb922063 restricted quickstats to the context of columns that lead an index.  Suddenly it makes sense why a clustered columnstore index would be an unexpected scenario for quickstats: columnstore indexes have no inherent sort of the data they contain.  So the quickstats query - if it succeeded - would have to perform a full scan.

OK, let's clean up after ourselves by dropping the extended events session.

DECLARE @sqlText4 NVARCHAR(1024) =
N'DROP EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256), @@SPID) +' ON SERVER';
EXEC (@sqlText4);

And what about a filtered index?

I've watched a lot of cop shows and detective shows.  Way before Steve Jobs and his "one more thing", there was Columbo and his "one more thing".

So, what happens if a filtered nonclustered index is put on the rowstore table rather than a plain old vanilla nonclustered index?

You know the drill...


IF OBJECT_ID('test_histogram_amendments') IS NOT NULL DROP TABLE test_histogram_amendments;
CREATE TABLE test_histogram_amendments(col1 BIGINT);
CREATE NONCLUSTERED INDEX nci_col1 ON test_histogram_amendments(col1)
WHERE col1 > 900000;

INSERT INTO dbo.test_histogram_amendments
SELECT TOP (1000000) nums.n
FROM dbo.getNums(1, 1000000) nums;
UPDATE STATISTICS test_histogram_amendments;
  
INSERT INTO dbo.test_histogram_amendments
SELECT TOP (1000) nums.n
FROM dbo.getNums(1000001,1001000) nums;

DECLARE @sqlText NVARCHAR(1024) = N'CREATE EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) 
+' ON SERVER 
  ADD EVENT sqlserver.sp_statement_completed(
      ACTION(sqlserver.sql_text)
      WHERE ([sqlserver].[session_id]=(' + CONVERT(NVARCHAR(256),@@SPID) +')))
  ADD TARGET package0.ring_buffer
  WITH (MAX_DISPATCH_LATENCY = 1 SECONDS);
  ALTER EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) 
  +' ON SERVER 
  STATE = START;';
EXEC (@sqlText);

EXEC sp_test_histogram_amendments

DECLARE @sqlText2 NVARCHAR(1024) =
N'ALTER EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +' ON SERVER
DROP EVENT sqlserver.sp_statement_completed;'
DECLARE @sqlText3 NVARCHAR(1024) =
N'SELECT sql_text
FROM
(     SELECT
        tab.event.value(''(event/data[@name="statement"]/value)[1]'', ''nvarchar(max)'') as [sql_text]
      FROM
    (   SELECT n.query(''.'') as event
        FROM
        (
            SELECT CAST(target_data AS XML) AS target_xml
            FROM sys.dm_xe_sessions AS s   
            JOIN sys.dm_xe_session_targets AS t
                ON s.address = t.event_session_address
            WHERE s.name = ''track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +'''
               AND t.target_name = ''ring_buffer''
         ) AS sub
        CROSS APPLY target_xml.nodes(''RingBufferTarget/event'') AS q(n)
    ) AS tab
) tab2
WHERE tab2.sql_text LIKE ''%StatMan%'';';
EXEC (@sqlText3);










We caught two stats queries this time.  What stats do we have?

SELECT st.name AS table_name, ss.name AS sts_name, 
       sp.last_updated, sp.rows, sp.unfiltered_rows, 
    sp.rows_sampled, sp.steps, sp.modification_counter
FROM sys.stats ss
JOIN sys.tables st ON ss.object_id = st.object_id 
CROSS APPLY sys.dm_db_stats_properties(ss.object_id,ss.stats_id) sp
WHERE st.name = 'test_histogram_amendments';


Got auto-generated stats on Col1, and the stats on the filtered index.  Strictly speaking, auto-generating stats on the column wasn't necessary: the test query is for the range over 1000000 and the filtered index covers that entire range.  But that will have to be for another day.









What I am really interested in is the quickstats query against the filtered index.

Check out the plan for that...












There it is. Full tablescan. SQL Server isn't using the filtered index... because there isn't a predicate on the quickstats query that matches the filtered index. Now since the filter on the filtered index has a lower bound but not an upper bound - if its populated the max value *is* the max value of Col1. But that's neither here nor there. Quickstats queries don't have WHERE clauses, at least not through SQL Server 2016. So when filtered indexes do qualify for quickstats queries due to trace flags 2389, 2390, or 4139... unless there is another *nonfiltered* index with the same lead column, a full tablescan will result.



With a very complex original query referencing the filtered query lead column multiple times in the predicate, the same quickstats query may be issued many times - each time leading to a full table scan. That can lead to really, really long query compiles.

And that's how the worlds of clustered columnstore, histogram amendments, and filtered indexes collide. Kb3189645 untangles this quite a bit. Clustered columnstore indexes and filtred indexes are both exempted from quickstats queries with this fix in place. So only nonfiltered ordered indexes will have quickstats queries issued against them for histogram amendments. There is a particular case where the filtered index is redundant to a nonfiltered index that could see performance degradation as a result of fix kb3189645... but that - like so many other things - must wait for another day.

Don't forget to drop the extended events session.

DECLARE @sqlText4 NVARCHAR(1024) =
   N'DROP EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256), @@SPID) +' ON SERVER';
EXEC (@sqlText4);














Thursday, January 5, 2017

SQL Server 2016 SP1 'dbcc clonedatabase' is swift & nifty

I think Microsoft has done a very good job of delivering technical documentation for SQL Server 2016 early in its life.

This kb is a good example.

How to use DBCC CLONEDATABASE to generate a schema and statistics only copy of a user database in SQL Server 2014 SP2 and SQL Server 2016 SP1
https://support.microsoft.com/en-us/kb/3177838/

Erin Stellato gave DBCC CLONEDATABASE a look in this blog post.

Expanding the uses of DBCC CLONEDATABASE
https://sqlperformance.com/2016/08/sql-statistics/expanding-dbcc-clonedatabase/

So among other assorted fun, today I did this on SQL Server 2016 SP1.

SET statistics time on
SET statistics io on
DBCC CLONEDATABASE (SRCE, LONNY_CLONE) WITH NO_QUERYSTORE

The resulting message.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
Database cloning for 'SRCE' has started with target as 'LONNY_CLONE'.
Database cloning for 'SRCE' has finished. Cloned database is 'LONNY_CLONE'.
Database 'LONNY_CLONE' is a cloned database. A cloned database should be used for diagnostic purposes only and is not supported for use in a production environment.
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

 SQL Server Execution Times:
   CPU time = 40643 ms,  elapsed time = 47261 ms.

So... what is in that new LONNY_CLONE database?

SELECT type_desc as item_desc, COUNT(*) as item_count 
FROM sys.objects 
WHERE is_ms_shipped = 0 AND
type_desc NOT IN ('SYSTEM_TABLE', 'INTERNAL_TABLE') 
GROUP BY type_desc
UNION ALL
SELECT 'columns' AS item_desc, COUNT (*) as item_count 
FROM sys.columns sc join sys.tables st ON sc.object_id = st.object_id 
WHERE st.type_desc = 'user_table' AND st.is_ms_shipped = 0
UNION ALL
SELECT 'qo_stat' as item_desc, COUNT (*) as item_count
FROM sys.stats ss 
JOIN sys.tables st ON ss.object_id = st.object_id
UNION ALL
SELECT 'nonclustered_index' as item_desc, COUNT (*) AS item_count 
FROM sys.indexes si 
JOIN sys.tables st ON si.object_id = st.object_id 
WHERE st.type_desc = 'user_table' AND st.is_ms_shipped = 0
AND si.type_desc = 'NONCLUSTERED'
UNION ALL
SELECT 'nondefault_schemas' AS item_desc, COUNT (*)
FROM sys.schemas WHERE schema_id BETWEEN 5 AND 16383
ORDER BY item_count DESC

There's plenty in there :-)


How big is the database?

SELECT file_id, type_desc,
CONVERT(NUMERIC(18,2), size * 8./1024.) AS size_mb
FROM sys.database_files


Not bad.  448 mb of database files, 968 mb of transaction log.

On a database with this much DDL (often databases like this have well over 60,000 query optimizer stats - this one just happened to be light in that area), using the scripts from SSMS to create a clone database can be really painful.  This is kinda fun :-)

This is going to be a great tool to enable investigating estimates and plan selection/shape.

Its a good thing that not every performance issue falls into those categories, or I'd have fewer edge cases to cherish. :-)

Thursday, December 29, 2016

SQL Server Trace flags 2389/2390/4139 ~ An Unadvertised Fix ~ Quickstats Queries for Filtered Indexes?

*****Update 20170103*****
OK, its fully-baked :-)
Yep, kb3189645 changes the behavior of the QO with respect to filtered indexes and quickstats.
When trace flags 2389, 2390, or 4139 are enabled on a system with kb3189645 filtered index stats are exempt from quickstats queries - even under the conditions which would lead to a quickstats query for a nonfiltered index.

So it's an unadvertised fix for Connect Item 2528743 😊 Look for the update within the blog post interior in purple to explain when Connect Item 2528743 can lead to such llllooonnngggg query plan compiles.

Trace flag 2390 can cause large compile time when dealing with filtered indexes. (Active)
https://connect.microsoft.com/SQLServer/feedback/details/2528743/

OK... where does that leave me for stuff to blog about later?

  • Show an example of a query with a filtered index that has a risk for poor plan quality with quickstats.  (Such a query is at risk for poor plan quality after kb3189645.)
  • Test the 'use hint' for histogram amendment introduced in SQL Server 2016 SP1.  Is it for legacy CE only?  Does it behave the same as trace flag 2389/2390/4139?

'k. 's enuff for now.
Ciao!
*****


The complete text of the test is at the bottom of this post. I won't consider this a fully-baked post until kb3189645 is confirmed responsible for the change I've seen in behavior related to quickstats queries & filtered indexes.

FIX: Access violation when you run a query that uses clustered columnstore index with trace flag 2389, 2390, or 4139
https://support.microsoft.com/en-us/kb/3189645

Here's my theory:
1. before kb3189645, clustered columnstore indexes were not exempt from quickstats queries to amend histograms.  If trace flag 2389, 2390, or 4139 lead to the optimizer issuing a quickstats query for a CCI, an access violation could result.  (I've seen these occur.  The AVs would prevent plan compile; an AV would even result from grabbing the estimated plan in SSMS.)
2. Kb3189645 resolved this by exempting CCIs from quickstats queries.
3. Kb3189645 also exempted filtered indexes from quickstats queries, whereas previous to kb3189645 quickstats queries could be issued against filtered indexes.

The kb in question is included in SQL Server 2014 SP1 CU9(build 12.00.4474) and SP2 CU2(build 12.00.5532).

Microsoft SQL Server Version List
https://sqlserverbuilds.blogspot.com/

The instances on which I compared behavior are SQL Server 2014 SP1 CU0 (build 12.0.4100) and SQL Server 2014 SP1-CU9-GDR (build 12.0.4487).

To begin, we borrow a function from Itzik Ben-Gan to efficiently create tables of consecutive integers.  Then create an Extended Events session specific to the spid used in the experiments, using the sp_statement_completed event.  The EE session is to capture the SQL query issued when quickstats are used to amend the histogram.  The EE session is created in a STOP state, state will change to START once a little closer to the specific behavior we want to observe. (I imagine there's a way to capture the quickstats queries outside of the context of a stored procedure and the sp_statement_completed event but I wasn't successful in finding it.) A table with integer columns NUM1 and NUM2, and an NVARCHAR column String1 is also created.  There's a filtered nonclustered index on (NUM1, NUM2), and a nonfiltered nonclustered index on (NUM2, NUM1).

SET NOCOUNT ON;
GO
CREATE FUNCTION dbo.GetNums(@low AS BIGINT, @high AS BIGINT) RETURNS TABLE
AS
RETURN
  WITH
    L0   AS (SELECT c FROM (SELECT 1 UNION ALL SELECT 1) AS D(c)),
    L1   AS (SELECT 1 AS c FROM L0 AS A CROSS JOIN L0 AS B),
    L2   AS (SELECT 1 AS c FROM L1 AS A CROSS JOIN L1 AS B),
    L3   AS (SELECT 1 AS c FROM L2 AS A CROSS JOIN L2 AS B),
    L4   AS (SELECT 1 AS c FROM L3 AS A CROSS JOIN L3 AS B),
    L5   AS (SELECT 1 AS c FROM L4 AS A CROSS JOIN L4 AS B),
    Nums AS (SELECT ROW_NUMBER() OVER(ORDER BY (SELECT NULL)) AS rownum
             FROM L5)
  SELECT TOP(@high - @low + 1) @low + rownum - 1 AS n
  FROM Nums
  ORDER BY rownum;
----------------------------------------------------------------------
-- © Itzik Ben-Gan
----------------------------------------------------------------------
/* http://tsql.solidq.com/SourceCodes/GetNums.txt */
GO

DECLARE @sqlText2 NVARCHAR(1024) =
N'CREATE EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +' ON SERVER 
  ADD EVENT sqlserver.sp_statement_completed(
      ACTION(sqlserver.sql_text)
      WHERE ([sqlserver].[session_id]=(' + CONVERT(NVARCHAR(256),@@SPID) +')))
  ADD TARGET package0.ring_buffer
  WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)';
EXEC (@sqlText2);
GO

CREATE TABLE [dbo].[X_TBL_QUICKSTATS](
       [NUM1]    INT,
       [NUM2]    INT,
       [String1] NVARCHAR(1024));

/* create filtered index and nonfiltered index sibling */
CREATE INDEX X_FILTERED_INDEX ON [X_TBL_QUICKSTATS] (NUM1, NUM2)
WHERE NUM1 > 1000000 AND NUM2 > 0;

CREATE INDEX X_INDEX ON [X_TBL_QUICKSTATS] (NUM2, NUM1);
GO

Then let's create the stored procedure with a query that will load the stats for the filtered index and the nonfiltered index. Someday I'll blog about queries which in past versions loaded filtered index stats but in SQL Server 2014 are able to get by with the filtered index stats header only. I had expected to see that with the new cardinality estimater; my tests showed that even with the legacy CE there were some changes. With enough rows in the table, the following query will do nicely.


/* create stored procedure with query to load filtered and nonfiltered index stats */
CREATE PROCEDURE X_SP_TBL_FILTERED_INDEX
AS
       SELECT
          (SELECT COUNT(NUM1) FROM [X_TBL_QUICKSTATS] WHERE NUM1 > 1000400 AND NUM1 < 1000501 AND NUM2 > 0) AS n1,
          (SELECT COUNT(NUM2) FROM [X_TBL_QUICKSTATS] WHERE NUM2 > 1000400 AND NUM2 < 1000501 AND NUM1 > 0) AS n2
       OPTION (RECOMPILE);
GO

Now its time to populate the table with rows, and update stats enough times to get the lead index column branded ascending or stationary.

/* insert 1000000 rows to start */
INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1,1000000) NUMS;

/* auto-update & sampled updates change when a leading column is branded ascending, use FULLSCAN to make predictable */
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

-- insert some data and update stats so T2388 shows leading columns as Ascending
INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000001,1000100) NUMS
ORDER BY NUMS.n;
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000101,1000200) NUMS
ORDER BY NUMS.n;
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000201,1000300) NUMS
ORDER BY NUMS.n;
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000301,1000400) NUMS
ORDER BY NUMS.n;
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

Immediately after the initial insert of 1000000 rows and four subsequent inserts of 100 rows, FULLSCAN stats updates were performed. Now let's add 100 more rows, outside of the range of the current histogram. And let's NOT update stats this time.

/* 100 more rows but no stats update */
INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000401,1000500) NUMS
ORDER BY NUMS.n;

Let's check the setup.

/* verify Leading columns are ascending and cardinality does not reflect most recent 100 rows */

dbcc traceon(2388) WITH no_infomsgs;
dbcc show_statistics ([X_TBL_QUICKSTATS], X_INDEX) WITH no_infomsgs;
dbcc show_statistics ([X_TBL_QUICKSTATS], X_FILTERED_INDEX) WITH no_infomsgs;
dbcc traceoff(2388) WITH no_infomsgs;

That's what we expect to see.  1000400 as "Table Cardinality" for the nonfiltered nonclustered index - even though there are now 1000500 rows in this index and the table.  400 as "Table Cardinality" for the filtered index, when there are 500 rows in the filtered index.  Both the nonfiltered and filtered index branded as ascending.


Before we start the EE session, let's execute the stored procedure once. This will auto-create column stats if necessary, and keep them out of the EE session.

EXEC X_SP_TBL_FILTERED_INDEX;


All right. Let's change the EE session state to START.

DECLARE @sqlText3 NVARCHAR(1024) =
N'ALTER EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +' ON SERVER 
STATE = START;';
EXEC (@sqlText3);

Now execute the stored proc.

/* 2389 - quickstats for Ascending
   2390 - quickstats for Unknown
   4139 - quickstats for Ascending, Unknown, Stationary
   9481 - force old CE, not valid before SQL Server 2014
   9204 + 3604 - which stats are loaded 
   For both of the counts below an unadjusted estimate will be 1 row */
DBCC TRACEON( 2389, 4139, 9481, 9204, 3604) with NO_INFOMSGS;
EXEC X_SP_TBL_FILTERED_INDEX;
DBCC TRACEOFF(2389, 4139, 9481, 9204, 3604) with NO_INFOMSGS;
/* SQL Server 2008 build 10.0.4000.0
   1st count has amended estimate of 200502 rows
   2nd count has amended estimate of 100 rows */

Dropping the event from the session "freezes" what we have in the ring buffer.

DECLARE @sqlText4 NVARCHAR(1024) =
N'ALTER EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +' ON SERVER
DROP EVENT sqlserver.sp_statement_completed;'

EXEC (@sqlText4);

What did we catch in our net?

DECLARE @sqlText5 NVARCHAR(1024) =
N'SELECT sql_text
FROM
(     SELECT
        tab.event.value(''(event/data[@name="statement"]/value)[1]'', ''nvarchar(max)'') as [sql_text]
      FROM
    (   SELECT n.query(''.'') as event
        FROM
        (
            SELECT CAST(target_data AS XML) AS target_xml
            FROM sys.dm_xe_sessions AS s   
            JOIN sys.dm_xe_session_targets AS t
                ON s.address = t.event_session_address
            WHERE s.name = ''track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +'''
               AND t.target_name = ''ring_buffer''
         ) AS sub
        CROSS APPLY target_xml.nodes(''RingBufferTarget/event'') AS q(n)
    ) AS tab
) tab2
WHERE tab2.sql_text LIKE ''%StatMan%'';';
EXEC (@sqlText5);

For SQL Server 2014 SP1, we see two different quickstats queries.  One query is issued twice - the query for NUM2, which is the first key of the nonfiltered index.  The query for NUM1 - which the filtered index has as leading column - occurs one time.

*****UPDATE 20170103*****
Here's why the behavior in this test case is potentially a BIG problem as Michael J Swart describes in Connect Item 2528743.  The quickstats query for the filtered index looks remarkably similar to the quickstats query for the nonfiltered index.  The quickstats query has no filter! (Like me at a holiday party 😜.) Without a WHERE clause that agrees with the filter of the filtered index, that query *can't* be satisfied by a single row read from the filtered index!  *If* there's another, unfiltered NCI on NUM1 it could be satisfied by a single row read from *that* index.  If *not* - full table scan required.
*****

Now let's take a look at the results on SQL Server 2014 SP1-CU9-GDR.  Still two queries for NUM2 - lead column for the nonfiltered index.  But no StatsMan query for NUM1 - no quickstats query for the filtered index.


*****
As I mentioned above at the top of the post, here is the entirety of the code to reproduce this test.
/*
DROP TABLE [X_TBL_QUICKSTATS]
DROP PROCEDURE X_SP_TBL_FILTERED_INDEX
DECLARE @sqlText1 NVARCHAR(1024) =
   N'DROP EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +' ON SERVER';
EXEC (@sqlText1); 
DROP FUNCTION dbo.GetNums
*/
SET NOCOUNT ON;
GO
CREATE FUNCTION dbo.GetNums(@low AS BIGINT, @high AS BIGINT) RETURNS TABLE
AS
RETURN
  WITH
    L0   AS (SELECT c FROM (SELECT 1 UNION ALL SELECT 1) AS D(c)),
    L1   AS (SELECT 1 AS c FROM L0 AS A CROSS JOIN L0 AS B),
    L2   AS (SELECT 1 AS c FROM L1 AS A CROSS JOIN L1 AS B),
    L3   AS (SELECT 1 AS c FROM L2 AS A CROSS JOIN L2 AS B),
    L4   AS (SELECT 1 AS c FROM L3 AS A CROSS JOIN L3 AS B),
    L5   AS (SELECT 1 AS c FROM L4 AS A CROSS JOIN L4 AS B),
    Nums AS (SELECT ROW_NUMBER() OVER(ORDER BY (SELECT NULL)) AS rownum
             FROM L5)
  SELECT TOP(@high - @low + 1) @low + rownum - 1 AS n
  FROM Nums
  ORDER BY rownum;
----------------------------------------------------------------------
-- © Itzik Ben-Gan
----------------------------------------------------------------------
/* http://tsql.solidq.com/SourceCodes/GetNums.txt */
GO

DECLARE @sqlText2 NVARCHAR(1024) =
N'CREATE EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +' ON SERVER 
  ADD EVENT sqlserver.sp_statement_completed(
      ACTION(sqlserver.sql_text)
      WHERE ([sqlserver].[session_id]=(' + CONVERT(NVARCHAR(256),@@SPID) +')))
  ADD TARGET package0.ring_buffer
  WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)';
EXEC (@sqlText2);
GO

CREATE TABLE [dbo].[X_TBL_QUICKSTATS](
       [NUM1]    INT,
       [NUM2]    INT,
       [String1] NVARCHAR(1024));

/* create filtered index and nonfiltered index sibling */
CREATE INDEX X_FILTERED_INDEX ON [X_TBL_QUICKSTATS] (NUM1, NUM2)
WHERE NUM1 > 1000000 AND NUM2 > 0;

CREATE INDEX X_INDEX ON [X_TBL_QUICKSTATS] (NUM2, NUM1);
GO

/* create stored procedure with query to load filtered and nonfiltered index stats */
CREATE PROCEDURE X_SP_TBL_FILTERED_INDEX
AS
       SELECT
          (SELECT COUNT(NUM1) FROM [X_TBL_QUICKSTATS] WHERE NUM1 > 1000400 AND NUM1 < 1000501 AND NUM2 > 0) AS n1,
          (SELECT COUNT(NUM2) FROM [X_TBL_QUICKSTATS] WHERE NUM2 > 1000400 AND NUM2 < 1000501 AND NUM1 > 0) AS n2
       OPTION (RECOMPILE);
GO

/* insert 1000000 rows to start */
INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1,1000000) NUMS;

/* auto-update & sampled updates change when a leading column is branded ascending, use FULLSCAN to make predictable */
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

-- insert some data and update stats so T2388 shows leading columns as Ascending
INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000001,1000100) NUMS
ORDER BY NUMS.n;
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000101,1000200) NUMS
ORDER BY NUMS.n;
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000201,1000300) NUMS
ORDER BY NUMS.n;
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000301,1000400) NUMS
ORDER BY NUMS.n;
UPDATE STATISTICS [X_TBL_QUICKSTATS] WITH FULLSCAN;

/* 100 more rows but no stats update */
INSERT INTO [X_TBL_QUICKSTATS] WITH (TABLOCK)
SELECT TOP (100) NUMS.n AS NUM1, NUMS.n AS NUM2, CONVERT(NVARCHAR(1024),NULL) AS String1
FROM dbo.GetNums(1000401,1000500) NUMS
ORDER BY NUMS.n;

/* verify Leading columns are ascending and cardinality does not reflect most recent 100 rows */

dbcc traceon(2388) WITH no_infomsgs;
dbcc show_statistics ([X_TBL_QUICKSTATS], X_INDEX) WITH no_infomsgs;
dbcc show_statistics ([X_TBL_QUICKSTATS], X_FILTERED_INDEX) WITH no_infomsgs;
dbcc traceoff(2388) WITH no_infomsgs;

/* Calling the sp here handles autocreate of column stats, keeps out of extended events observation 
   Actual plan should show estimate of 1 row for both counts if no trace flag 2389, 2390, 4139 active */
EXEC X_SP_TBL_FILTERED_INDEX;

DECLARE @sqlText3 NVARCHAR(1024) =
N'ALTER EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +' ON SERVER 
STATE = START;';
EXEC (@sqlText3);

/* 2389 - quickstats for Ascending
   2390 - quickstats for Unknown
   4139 - quickstats for Ascending, Unknown, Stationary
   9481 - force old CE, not valid before SQL Server 2014
   9204 + 3604 - which stats are loaded 
   For both of the counts below an unadjusted estimate will be 1 row */
DBCC TRACEON( 2389, 4139, 9481, 9204, 3604) with NO_INFOMSGS;
EXEC X_SP_TBL_FILTERED_INDEX;
DBCC TRACEOFF(2389, 4139, 9481, 9204, 3604) with NO_INFOMSGS;
/* SQL Server 2008 build 10.0.4000.0
   1st count has amended estimate of 200502 rows
   2nd count has amended estimate of 100 rows */

DECLARE @sqlText4 NVARCHAR(1024) =
N'ALTER EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +' ON SERVER
DROP EVENT sqlserver.sp_statement_completed;'

EXEC (@sqlText4);

DECLARE @sqlText5 NVARCHAR(1024) =
N'SELECT sql_text
FROM
(     SELECT
        tab.event.value(''(event/data[@name="statement"]/value)[1]'', ''nvarchar(max)'') as [sql_text]
      FROM
    (   SELECT n.query(''.'') as event
        FROM
        (
            SELECT CAST(target_data AS XML) AS target_xml
            FROM sys.dm_xe_sessions AS s   
            JOIN sys.dm_xe_session_targets AS t
                ON s.address = t.event_session_address
            WHERE s.name = ''track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +'''
               AND t.target_name = ''ring_buffer''
         ) AS sub
        CROSS APPLY target_xml.nodes(''RingBufferTarget/event'') AS q(n)
    ) AS tab
) tab2
WHERE tab2.sql_text LIKE ''%StatMan%'';';
EXEC (@sqlText5);

SELECT @@version
/* On version Microsoft SQL Server 2014 (SP1-CU9-GDR) (KB3194722) filtered indexes appear to be exempted.
sql_text
SELECT StatMan([SC0]) FROM (SELECT TOP 1 [NUM2] AS [SC0] FROM [dbo].[X_TBL_QUICKSTATS] WITH (READUNCOMMITTED)  ORDER BY [SC0] DESC) AS _MS_UPDSTATS_TBL  OPTION (MAXDOP 1)
*/

DECLARE @sqlText6 NVARCHAR(1024) =
N'ALTER EVENT SESSION track_sql_text_spid_' + CONVERT(NVARCHAR(256),@@SPID) +' ON SERVER
STATE = STOP;'
EXEC (@sqlText6);