I’ve mentioned previously how not having up to date statistics can cause problems in query performance. This post looks at something called the Ascending Key Problem which can badly affect your cardinality estimation in some cases and therefore your execution plans.

The Ascending Key Problem relates to the most recently inserted data in your table which is therefore also the data that may not have been sampled and included in the statistics histograms. This sort of issue is one of the reasons it can be critical to update your statistics more regularly than the built-in automatic thresholds.

We’ll look at the problem itself, but also some of the mitigations that you can take to deal with it within SQL Server.

The Problem

Imagine you have a table that stores a set of events. As new records are inserted they get stamped with the current date and time. You regularly query that table based on that EventDate looking to find recent events, let’s say just for the current day.

Even if you haven’t indexed the EventDate column (though why haven’t you?!), as long as you have AUTO CREATE STATISTICS and AUTO UPDATE STATISTICS on for your database you’ll have “reasonably” up to date statistics for that column.

But “reasonably” may not be good enough. When you’re querying against the most recent data it may not yet have been sampled by a statistics update and the range you are looking for may fall beyond the top of the histogram captured in the statistics object for EventDate. Imagine that statistics were last updated yesterday. When the Optimizer checks the statistics to estimate a rowcount for today’s date it finds that is above the top bound. So what should it guess?

Historically it would guess that there were zero rows, but as always the cardinality estimation gets set to the minimum of 1. If the real answer is a lot larger you might end up with a bad plan.

Let’s look at that in practice.

Staying true to the example above, I create a table called Events and I index the EventDate column:

CREATE TABLE dbo.Events
(
Id INT IDENTITY(1,1) CONSTRAINT PK_Events PRIMARY KEY CLUSTERED,
EventName VARCHAR(255) NOT NULL,
EventDate DATETIME CONSTRAINT DF_Events_EventDate DEFAULT (GETDATE())
);

CREATE INDEX IX_Events_EventDate ON dbo.Events(EventDate) include (EventName);

Then I insert records to represent events at one minute intervals for 100 days:

--Insert data for 100 days at minute intervals from the start of this year
DECLARE @StartDate DATETIME = '20170101 00:00.00';

INSERT INTO dbo.Events(EventName, EventDate)
SELECT
    'Event' + CAST(num.n AS VARCHAR(10)),
    DATEADD(minute,num.n,@StartDate)
FROM 
(
    SELECT TOP 144000 row_number() OVER(ORDER BY (SELECT NULL)) AS n 
    FROM sys.objects a, sys.objects b, sys.objects c
) num;

I’m going to query to check what date range was inserted. That should have the additional advantage of triggering a statistics update:

SELECT MIN(EventDate), MAX(EventDate)
FROM dbo.Events;

As a slight digression, it’s interesting to look at the execution plan here:

You can see two index scans. That sounds horrendous, scan the index twice to find the MIN and MAX? If you look at the properties though you can see it only read one row in each case:

An index scan doesn’t have to read all the records in the index, it can bail out once it is satisfied. For a MIN or MAX type query it makes perfect sense just to jump to one end of the index and start scanning.

The side lesson is that Scans aren’t always bad for performance.

Anyway, back to the topic in hand. Now let’s look at the statistics:

DBCC SHOW_STATISTICS('dbo.Events',IX_Events_EventDate);

You can see they’re up to date. They show 144,000 rows in total which is correct. Interestingly the Histogram (bottom result-set) only has a couple of steps. SQL has determined that the data is uniformly distributed so has bunched it altogether. Clever stuff!

Let’s insert data for another day:

--Insert one more day's data
DECLARE @StartDate DATETIME;

SELECT @StartDate = MAX(EventDate) FROM dbo.Events;

INSERT INTO dbo.Events(EventName, EventDate)
SELECT
    'Event' + CAST(num.n AS VARCHAR(10)),
    DATEADD(minute,num.n,@StartDate)
FROM 
(
    SELECT TOP 1440 row_number() OVER(ORDER BY (SELECT NULL)) AS n 
    FROM sys.objects a, sys.objects b, sys.objects c
) num;

Now I query to see the new events. I captured the MAX(EventDate) earlier so let’s use that to find the new records:

SELECT *
FROM dbo.Events
WHERE EventDate > '20170411'
OPTION (RECOMPILE);

(Notice I’ve added the option to recompile so I get a fresh plan each time I run this, that will be important for testing)

Let’s not bother with the results, we all know there will 1,440 records that are basically the same. Here’s the execution plan:

The interesting bit comes when I look at the properties for the Index Seek:

Estimated number of rows = 1, Actual = 1,440. That’s quite a long way out. Of course here we have a trivial query so the massive underestimate isn’t affecting our plan. If we started joining to other tables though it would likely result in a massively inefficient plan – perhaps choosing a Nested Loops join over a Hash or Merge.

Note I’m using SQL Server 2012 for this test and I’m not using the Traceflag (2371) which reduces the threshold for statistics updates ( When do Statistics Get Updated? ):

So I’ve got nearly another 30,000 rows to insert before statistics get automatically updated and my estimates come into line. If I’m always querying for the current day then it’s going to be very rare that statistics are going to be able to help me with a good estimate.

So what’s the fix?

Before we get on to the methods that have been introduced to try and ameliorate this problem, if you face this sort of scenario you might want to consider whether you need to update your statistics objects more often than the auto-stats threshold. If you have a regular job to rebuild fragmented indexes then those indexes that get rebuilt will have their statistics refreshed – however that won’t cover the auto created statistics, and it won’t cover statistics for tables that get don’t get rebuilt.

So, if you don’t have a specific scheduled job to regularly update statistics that is definitely worth considering.

In terms of how SQL has changed to help us, from SQL Server 2005 SP1, the nature of columns began to be tracked, monitoring updates of statistics to understand how the data changes. This additional information can be seen if you enable traceflag 2388, then view the statistics. Let’s have a look at what’s gathered. First I’m going to add a couple more days of data, updating the statistics between each insert, then I run the following:

DBCC TRACEON(2388);
DBCC SHOW_STATISTICS('dbo.Events',IX_Events_EventDate);
DBCC TRACEOFF(2388);

What you see here is historical information about the updates to the statistics. This is undocumented stuff, but some of what we see we can work out the meaning for. In particular we can see how many rows were inserted since the last statistics update, and how many of those values were above the top of the old histogram. We also see a column “Leading Column Type” which has a value of “Unknown”.

Now I’m going to insert another day’s date and update the statistics once more, then we’ll look at this again:

You can see that now we have a Leading Column Type of “Ascending”. After three updates to the statistics where the Leading Value was only increasing each time, SQL Server will identify that it is an ascending column. It must be at least three updates before SQL will recognise this, and if that stops being the case (i.e. some lower values are inserted) then the next statistics update will reset this until we again get three consecutive updates with only increasing values.

This happens in the background and you don’t need the traceflag 2388 to make it happen –that is just so you can see what is going on.

The obvious question is, now SQL knows my column is ascending, has that affected the estimation for my query? Before we look I’ll insert another day of data so there is some data beyond the histogram, and then I’ll query again:

SELECT *
FROM dbo.Events
WHERE EventDate > '20170415'
OPTION (RECOMPILE);

And the properties from the execution plan:

So nope. Nothing has changed.

Yet…

To tell the query optimizer to take advantage of this extra information for ascending keys we have traceflag 2389. Let’s enable that and run the query again:

DBCC TRACEON(2389);

SELECT *
FROM dbo.Events
WHERE EventDate > '20170415'
OPTION (RECOMPILE);

The properties:

Voila! SQL Server has now estimated my rowcount perfectly.

Now, be warned. This is a rather contrived example with a perfectly and artificially smooth distribution of data. The estimate is made by checking the current maximum value in the table, and using that combined with the information existing in the statistics and the value of your predicate to extrapolate a guess. If you’re data is evenly distributed as it is here then the guess will be pretty good, if it is fairly skewed then it may be bad.

In any case though it will probably be better that the fixed value of 1 that would have been used historically.

One thing to note is that traceflag 2389 is only going to have any affect if the leading column of the relevant statistics object has been marked as ascending. There is also traceflag 2390, and this will adopt a similar behaviour even if your column hasn’t been identified as ascending, i.e. it will check the maximum value in the table and if it is higher than the max value in the histogram, it will extrapolate to work out the cardinality estimate.

So should you turn on the traceflag(s) globally?

The Microsoft recommendation is not to enable traceflags such as these unless you are suffering from the specific problem they are aiming to resolve, and even then to make sure you test carefully to ensure they are achieving what you desire.

One issue can be that in more complex queries there are a number of cardinality estimates being made. It can be that two bad estimates within the same plan might cancel each other out and the query overall performs fine. If you then implement something that fixes one of them, you risk such queries going bad – a scenario known as plan regression.

This sort of scenario is one of the reasons why Microsoft have made very few core changes to the cardinality estimator since it came out.

So, use 2389 is you are specifically encountering this sort of ascending key problem, but also, if you are in the position to change the code then you might want to consider adding it as a query hint so it only affects the specific query you are targeting. For our example query above, that would simply look like:

SELECT *
FROM dbo.Events
WHERE EventDate > '20170415'
OPTION (RECOMPILE, QUERYTRACEON 2389);

Welcome to SQL Server 2014 (and later)

In 2014 we received a substantial revamp of the Cardinality Estimator, the first since SQL Server 7.0. A bunch of assumptions and algorithms have been re-jigged based on the real-world data that Microsoft have seen in supporting their wide customer base.

Key to having a new version was the concept that, henceforth, optimizer fixes would be tied to the database compatibility version. This means that customers can upgrade their SQL Server version but if they find performance problems related to the upgrade they can downgrade their database’s compatibility level while the issues are resolved within their codebase.

One of the items specifically looked at in the new version was this Ascending Key problem. To see how things work in the latest versions I’m going to repeat many of the steps above using a database deployed on SQL Server 2016.

So I:

• Create my table again
• Populate with the 100 days data
• Run a query to check the dates, which has the added benefit of updating statistics
• Add one more day’s data

Then I’m ready to run my test query again:

SELECT *
FROM dbo.Events
WHERE EventDate > '20170411'
OPTION (RECOMPILE);

I get the same execution plan as ever so again I jump to the properties of the Index Seek operator to look at the estimates:

Now, this is interesting. I might have expected I would get either 1 row estimated (the old model) or 1,440 (the model with traceflag 2389). Instead I get 432 rows. It seems the new CE (Cardinality Estimator) uses a different algorithm.

Sometimes numbers stick in your head. I happen to know that where no statistics are available and you are querying with an inequality predicate (<, > , <=, >=) that the CE will estimate the number of rows to be 30% of the total number of rows in the table. This assumption seems to have originated in a 1979 research paper from IBM suggesting 1/3 was a good guess.

With 30% in my head I noticed that 432 is 30% of 1440. So it seems that the optimizer is recognising that we are querying for values above the histogram (where no statistics exist) with an inequality, it knows from somewhere that there have been 1440 rows inserted since the last statistics update, so it takes 30% of 1440 to produce the estimate (432).

To try validate that theory I thought I’d query with a later datetime in the predicate. Sure enough, if I add 12 hours I still get 432 rows estimated. If I add 23 hours, 432 rows. In fact if I query for any date in the future, even outside of the maximum value in the table, guess what – I get an estimate of 432 rows.

I have a fascination for the algorithms involved in distribution statistics. It satisfies the maths geek in me. As such it’s difficult to end a post like this, there’s always more things to test, to try and work out. For instance what happens if you query across an interval that starts within the current histogram, but then extends above it? I’ll admit I’ve had a play, but will leave that for another post.

As a very final point in this post, I thought I’d just check whether the 2389 traceflag makes any difference to this estimation with the 2014 CE. I’ll change my query to look way into the future, enable the traceflag and look at the estimate:

SELECT *
FROM dbo.Events
WHERE EventDate > '99991231 23:59:59'
OPTION (RECOMPILE, QUERYTRACEON 2389);

Guess what? Still 432 rows… so no, the traceflag doesn’t appear to still give us any

Got a problem or embarking on a SQL Server project and want some help and advice? I’m available for consulting – please get in touch or check out my services page to find out what I can do for you.extra benefit.
Though when we get to that date it’ll be someone else’s problem to sort out!

This is a blog devoted to databases, but for once I’m going to go off topic and talk about something I did at the weekend that I’ve never done before. On Easter Sunday I went to London to join in a protest demanding action on climate change.

I’d heard about what Extinction Rebellion were doing for a while. Initially I was put off by the name which I felt made them sound a bit like an anti-capitalist movement and I felt that for us to effect change we need to embrace people from all sides of the political spectrum. I also wasn’t sure how I felt about the actions they were taking – blocking roads and traffic. Was that going to antagonise more people than it gathered support?

In the end though I figured they were at least doing something – and something needed to be done. I’d lost faith that governments were going to act in time to avert disaster. I decided I wanted to show my support, add one more person to the weight of people demanding action. I didn’t want to get arrested but felt that at least being there was something. From their website I discovered there were all sorts of ways to get involved.

I went with Lisa my fiancee, and Millie our dog.

We got the train up to London from Bristol on Sunday morning and headed to the legal protest site near Marble Arch. At first it was confusing. Who could we talk to about being involved? What could we do? We found an induction session that had just started and sat down to join in.

As the leaders of the session talked about their background, their ethos, their aims and methodology I was quickly impressed. They stressed that this was not just a socialist movement, that they recognised they needed to engage people from all walks of life and ideologies.

I was most impressed by the strong focus on non-violent, non-aggressive action. That in all interactions with the police or public, those involved should make sure they were peaceful and reasonable at all times, whatever was going on. That if anyone witnessed someone against going against that guiding principle they should either intervene or find someone else to do so, to suggest to the perpetrator that this was the wrong movement for them. And they managed to make this work, in all arrests and actions there wasn’t a single report of violence or wilful destruction.

I get that some people were frustrated by their actions and the disruption it caused, and I empathise with anyone affected, but they explained that they hadn’t undertaken their actions lightly. Hundreds of thousands of people had attended climate marches to little effect. They knew they needed to do something different and things were becoming more urgent. Research was undertaken looking at movements in the past that were succesful in achieving their aims and it was dicovered that the common theme was creating disruption in a peaceful manner. Only through the threat of continued disruption were authorities forced to take notice and engage with the movements in question.

Marble Arch is a busy place, with lots of people milling around or wandering to the nearby Hyde Park. Lisa and I decided we could best involve ourselves by chatting to people passing by, handing out flyers and explaining to people what was going on and why. Talking to people about the urgency of action and some of the dangers to us all if nothing happens.

We had a lot of nice interactions, and maybe even changed a couple of minds. Millie was a big hit as a protester (it was her first protest too) and a great draw to start a conversation. In particular the police loved her! That was another great thing, to see how good natured the police were through it all, smiling, laughing and posing for pictures with protesters.

All in all it was a surprisingly nice day out and very inspiring. There were times when I felt myself getting quite emotional. It’s definitely something I’d do again.

From the media since it seems like there has been some impact, but there’s a long way to go. If you’re the slightest bit concerned about climate change – and I hope you are – I’d encourage you to get involved. Even if you just sign up on their website or add your name to petitions that circulate. Or you could make a donation, or attend one of their actions.

https://rebellion.earth/

You can particpate in whatever way you feel comfortable with.

I strongly believe that this is the biggest issue of our time, and without enough being done it could be the biggest issue of all time. We all need to do what we can.

Thanks for reading!

I’ve recently encountered an issue that was difficult to resolve and I didn’t find the particular cause that was troubling us documented elsewhere on the web so thought I’d record it here.

The issue was with a service account connecting to SQL Server and intermittently failing to logon.

Errors reported in the Windows Application Event log were:
SSPI handshake failed with error code 0x8009030c
Login failed. The login is from an untrusted domain and cannot be used with Windows authentication.

The login attempt didn’t appear to get as far as the SQL instance, so no further information could be captured in a failed Logins trace.

This was affecting a large number of application servers using the same service account. Fortunately this was in development and test environments so no production impact.

The problem was that the account was getting locked out. A service was running every half hour using the account to connect to SQL, but with the wrong password. We also had a process running to unlock locked service accounts – so the account would start working again after a few minutes.

The resolution was to kill that service as it was no longer required. We were able to identify where the failed logins were coming from via the Active Directory audit logs for the account in question.

This was particularly difficult to troubleshoot as the error was a bit misleading.

There were a couple of other sources I came across while trying to google the cause of the problem. I’ve updated those with the cause we found as well:
https://blogs.msdn.microsoft.com/docast/2016/02/11/common-sspi-handshake-failed-errors-and-troubleshooting/#comment-7075
https://stackoverflow.com/questions/1538027/sspi-handshake-failed-with-error-code-0x8009030c-while-establishing-a-connection

Hopefully this post will save someone else the many hours of investigation I’ve just been through!

Got a problem or embarking on a SQL Server project and want some help and advice? I’m available for consulting – please get in touch or check out my services page to find out what I can do for you.

When I’m using Profiler to analyse performance issues I often save the results to a table, or upload a trace file into a table, so that I can analyse the data. Often this involves aggregating the values for particular queries so that I can see the most resource hungry.

This is by no means a difficult process, but with Extended Events (XE) it’s arguably even easier.

Let’s start with a session from XEvent Profiler like we saw in my last post on this subject:

Extended Events Made Easy: Using XEvent Profiler

I’ve set a workload running and captured the Live Data. The workload consists of some arbitrary queries I’ve written, each running in a loop in its own query window.

After a few minutes I stop the session so I can do my analysis:

I’ve got a couple of hundred events. Let’s say I want to quickly find the longest running individual query. In the Live Data viewer you can just right-click on the column name and select sort ascending or descending. This is pretty obvious stuff, but I thought it was worth highlighting as you can’t do the same in Profiler – there you have to save to a table first then query the table.

So, I’ve sorted descending on Duration:

You can see the biggest values shown are the aggregated values for the existing_connection and logout events. In retrospect it might have been better to create an XE session that didn’t include these events. However, I look down the list and quickly find my longest running query (highlighted in blue).

The duration specified – 33,161,516 – is in microseconds. So that is just over 30 seconds.

Of course, now I’m thinking – that’s my longest running, but what I really want is the one that has the most CPU – and not just from one execution but the total from all the executions that happened in my sample time frame.

This is where I can use grouping and aggregation. I can right-click on any of the columns and select “Group by this column”. I’m going to do that for the TextData column:

We’re now seeing all the events from the sample time period, grouped together based on TextData. The number on the right of each one is the count of events in that group.

Now I can add some aggregations. After grouping I still can see the original column headings at the top, so I just right-click on cpu_time, select “Calculate Aggregation” and select “SUM”:

You’ll see you can pick the other standard aggregations also e.g. MIN, MAX, AVG etc.

You can have multiple aggregations going on, so I’ll do the same for duration and logical_reads.

Once I have my aggregations in place, I’ll want to sort the results. It’s the total cpu_time I’m most interested in so I right-click on that column and now I have the option to “Sort Aggregation Descending”:

After those steps this is what I end up with (I’ll just show the top few rows):

Admittedly this isn’t the most beautiful of views, but it was quick and easy to get to and it gives me the information I need. I can see my most CPU hungry queries and I can make a plan of action.

Incidentally, the top query was:

UPDATE dbo.Test SET SomeText = 's' + SomeText WHERE SomeText LIKE 's%'

If this wasn’t a totally arbitrary set of queries for demo purpose I might be considering putting an index on the SomeText column.

That’s all I wanted to cover in this post. Hopefully you can see that XE data is really easy to work with, you don’t have to get involved in XML querying and you can perform quick analysis without even having to write SQL – much as we all love writing SQL.

In the last couple of posts, I’ve looked at how easy it is to get started using XE with the XEvent Profiler. For the next post in this series I aim to demonstrate that it’s also really easy to create your own customizable Extended Events sessions.

Previous posts in this series:

There’s Still a Place for SQL Server Profiler

Using the built-in System Health session

Exporting Extended Events Session Data to a Table

Extended Events Made Easy: Using XEvent Profiler

Got a problem or embarking on a SQL Server project and want some help and advice? I’m available for consulting – please get in touch or check out my services page to find out what I can do for you.

For this month’s T-SQL Tuesday. Jeff Mlakar invites to talk about “a project you worked on or were impacted by that went horribly wrong”:

https://www.mlakartechtalk.com/t-sql-tuesday-107-invitation-death-march/

I’m not sure the story I’m about to share is exactly what Jeff was looking for, but when you say failed project, this one usually comes to mind.

This is from one of my first roles as a developer, back when I was writing VB code and before I got into SQL Server. This was even before .NET. At the time I was working for an engineering company that dabbled in a few pieces of very specific software for the industry. I’d taken the job so I could develop my coding skills by working with a proper software development team. Only to discover when I started, that I was the development team – the others had left.

So… I worked on this piece of software. It was one of those productivity tools that had a very specific use in a very specific type of project. There was nothing else that did what it did in Windows. Without it you were required to do a lot of hand-cranked analysis using Fortran, or if you were really unfortunate, paper and a pencil. The licences sold for big bucks per seat – but there were only about 20 customers worldwide for whom it might be useful.

I’d been working on a shiny new version. As part of that, I was tasked with creating a demo that we could send to all those clients. The main thing was that it had to have full functionality but be limited to working with a sample dataset. The company were currently in litigation with one client who they’d given a copy for eval, but who’d then used it for completing a big piece of work within a six figure contract. They didn’t want a repeat of that.

My boss wanted to create an auto-run menu for the CD – we’d only just moved over to CDs from having to create 10 floppy disks for each install. An auto-run was the latest and greatest pinnacle of slickness. I gave him a few lessons in creating forms and buttons in VB and off he went.

My boss burnt the CDs one Friday, including his fancy menu executable. He packaged them up with the relevant sales brochures and sent them out. He then went off on holiday for a fortnight.

I came in on the Monday morning to an urgent email from one of our senior managers. Apparently one of the recipients of the CD was reporting that they had put it in a desktop and that it had installed a virus on their system. Testing verified that they were correct. The auto-run menu program did indeed have a fairly nasty virus hiding in the executable, and because it was in the auto-run, all they needed to do to get infected was put the CD in their drive.

Basically, my boss used to use his work PC for downloading hacked “warez” from happyhippo.com. His work desktop had become badly infected and that had spread to the executable he worked on and compiled.  As he wasn’t around to own the issue, a colleague and myself had the fun of calling all the people we’d sent the demo to, asking them if they’d put the CD in any of their computers. If they hadn’t we told them to destroy it. If they had, then we had to talk them through the lengthy process to get rid of the virus.

As a marketing exercise this wasn’t a stunning success.

I often tell friends in the software business this story as a consolation when they feel responsible for some mess up. “Well, at least you didn’t send a virus infected demo to your entire prospective customer base like my old boss did”

I left that company not longer after.