To warn you ahead of time, this post is an exploration without an answer (yet). There’s some interesting stuff in here, but no conclusions. If that’s not your kind of post, feel free to skip it. If it is, well, here goes nothin’…
Wild, Wild Life
Creating indexes is kind of a funny thing. By the time you find the query that needs one, figure out which index will help, go through change management, and check it into source control and roll it out in production whenevs, you’re almost not even worried anymore. You’ve already been through h*ck, why would SQL Server make you suffer more?
Now, to be fair, all sorts of things can contribute to indexes creating slowly. A busy server, blocking, crappy I/O, not enough memory, creating really wide indexes, etc.
All totally legit reasons for it, too. It’s a database, not a genie here to grant your wishes because you’ve got a magic rub.
Ruling Reasonable Things Out
On my desktop, I don’t have any of those problems. I’m the only user, I’m not blocking myself, I have a 1TB NVMe card, and I’m creating, in these examples, single column indexes on integer columns.
To further rule out any hanky panky, I’m gonna create the indexes offline. Creating indexes online is a bit more complicated, though doing this exhibits the same pattern.
Here are the indexes I’m going to create.
|
1 2 3 4 5 6 7 8 9 10 |
CREATE INDEX ix_whatever ON dbo.Comments (UserId) WITH (ONLINE = OFF, MAXDOP = 6); GO CREATE INDEX ix_apathy ON dbo.Comments (Score) WITH (ONLINE = OFF, MAXDOP = 6) GO CREATE INDEX ix_ennui ON dbo.Comments (PostId) WITH (ONLINE = OFF, MAXDOP = 6); GO |
Why MAXDOP 6? Because I have 6 physical cores in my desktop. There are those among us who loathe hyperthreading, and would surely cast their cursed stones upon my Great Post.
The Comments table has 68,343,743 rows in it. Not a lot, but not a little, either. It’s a moderately sized table, depending on who you talk to.
Heat Rash
Starting with no indexes on the table, I’m going to create these in order. This isn’t a case of indexes helping indexes. They all do the same number of reads, but…
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
/*UserId*/ Table 'Comments'. Scan count 7, logical reads 2850853, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0. SQL Server Execution Times: CPU time = 109906 ms, elapsed time = 19565 ms. /*Score*/ Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0. Table 'Comments'. Scan count 7, logical reads 2850853, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0. SQL Server Execution Times: CPU time = 109357 ms, elapsed time = 57679 ms. /*PostId*/ Table 'Comments'. Scan count 7, logical reads 2850853, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0. SQL Server Execution Times: CPU time = 62283 ms, elapsed time = 11133 ms. |
What in the heck did that index on Score do? Why does it take a full minute to get created? And… Why did it need a worktable?!
Plans, Man
The first clue is in the query plans.
You may notice something slightly different about these plans. The top and bottom indexes, the ones that are created quickly, are fully parallel. The slow index on Score starts out parallel, but ends up serial for the insert into the index. That’s also the one that needed the worktable.
This is upsetting. That Gather Streams and serial insert cause the index creation to take a much longer time. Why could that be?
Could It Be NULLs?
At first glance, I thought I had something, but this isn’t the answer. UserId and Score are both NULLable, but only Score results in an early-serial plan.
Imagine if I could give you a really good reason like this to use default values.
But this ain’t it. Throw that dream away.
Density Vector?
My next guess was that it was based on the number of distinct values in a column. I don’t think that’s quite true either. Columns with totally different distributions would get the serial insert plan.
For example, the AcceptedAnswerId column on the Posts table:
|
1 |
<a style="background-color: #ffffff; font-family: -apple-system, BlinkMacSystemFont, 'Segoe UI', Roboto, Oxygen-Sans, Ubuntu, Cantarell, 'Helvetica Neue', sans-serif; font-size: 16px;" href="https://www.brentozar.com/wp-content/uploads/2018/12/2018-12-07_21-02-17.jpg"><img class="size-full wp-image-197906" src="https://www.brentozar.com/wp-content/uploads/2018/12/2018-12-07_21-02-17.jpg" alt="" width="224" height="158" /></a> |
No sir.And the Score column on the Comment table:
These both get the much slower serial insert treatment, but have very different value distributions. There are other columns with similar value distributions that get parallel inserts. I won’t bore you by showing you all of them. Just know that they’re out there, and that I couldn’t discern a pattern.
Sort Of Different
Going back to the query plans for the create index statements on Comments, there’s a strange difference in the Sort operations.
The two indexes that create quickly have a Partition ID — this table isn’t partitioned at all.
And there’s also a difference in the wait stats each plan generates.
The fast plans have QUERY_EXECUTION_INDEX_SORT_EVENT_OPEN in the wait types, which is described at the link as:
Occurs in certain cases when offline create index build is run in parallel, and the different worker threads that are sorting synchronize access to the sort files.
Which would explain why the sorts for the parallel inserts have a Partition ID, and why the Gather Streams of the serial insert is order preserving.
Last Stop
To verify that the order preserving Gather Streams is where the slowdown hits, I turned on Live Query Plans. Though the plans don’t show up while the index creates are executing, they do preserve the Actual Time statistics of each operator, over in the properties window (hit F4 while looking at a query plan). And indeed, Gather Streams is a full 40 seconds of the 57 second total time.
Unfortunately, there’s not a good, practical way to compare a plan that avoids the worktable, and does a parallel insert into the index. One could try messing with STATS_STREAM, if one were feeling particularly big-brained, but that’s a pretty far leap away from “practical”.
Closedown
I wish I had better answers as to why these different plans get chosen. The bottom line is that I can find lots of places that offer differences, but no place that offers insight. I’ve been in the debugger. I’ve been in PerfView. I’ve been in all sorts of Trace Flags. At some point, I gotta give in and write down what I’ve found. Because I mentioned it earlier, here are the plans for the online versions.
It would be nice to have some control over this stuff when creating and rebuilding indexes.
Rebuilding indexes?
Yep.
Something lousy happens there, too.
The ride never ends.
Thanks for reading!
6 Comments. Leave new
Were you able to get more insights and how can we avoid this behaviour
No.
PostId and UserId are foreign key columns but score is not.
The Stack Overflow database doesn’t have foreign keys.
How fragmented was that PK when you started this test? With a FillFactor = 0 and if many inserts having occurred before the test, who knows what you’ll get since the data is all over the place in the pages. I would have started this test with a full rebuild of the PK to make sure the table and stats were 100% from the beginning. At least address it as a possibility.
By all means, if you think that’s the culprit, go for it! That’s why our blog posts all use open source databases – so you can run your own experiments to test your hunches, and then report back.