I need to be up front with you, dear reader, and tell you that you’re probably never going to need to know this.
I try to blog about stuff people need to know to get their job done – things that will be genuinely useful in your day-to-day performance tuning and management of SQL Server. This, however, is not one of those things. This is fun, obscure trivia, documenting a situation you’ll probably never run into, prompted by Forrest’s post proving that compilation time includes more than parse time.
Start with a hard-to-compile query plan.
I’ll use any Stack Overflow database and the hard-to-compile query plan from my post, Bad Idea Jeans: Building Big Query Plans, modified to join to the Users table:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
SET STATISTICS TIME ON; GO DECLARE @TheRootOfAllEvil TABLE (Id INT PRIMARY KEY CLUSTERED); WITH CTE1 AS (SELECT * FROM @TheRootOfAllEvil r1), CTE2 AS (SELECT cA.* FROM CTE1 cA INNER JOIN CTE1 cB ON cA.Id = cB.Id), CTE3 AS (SELECT cA.* FROM CTE2 cA INNER JOIN CTE2 cB ON cA.Id = cB.Id), CTE4 AS (SELECT cA.* FROM CTE3 cA INNER JOIN CTE3 cB ON cA.Id = cB.Id), CTE5 AS (SELECT cA.* FROM CTE4 cA INNER JOIN CTE4 cB ON cA.Id = cB.Id), CTE6 AS (SELECT cA.* FROM CTE5 cA INNER JOIN CTE5 cB ON cA.Id = cB.Id), CTE7 AS (SELECT cA.* FROM CTE6 cA INNER JOIN CTE6 cB ON cA.Id = cB.Id), CTE8 AS (SELECT cA.* FROM CTE7 cA INNER JOIN CTE7 cB ON cA.Id = cB.Id), CTE9 AS (SELECT cA.* FROM CTE8 cA INNER JOIN CTE8 cB ON cA.Id = cB.Id) SELECT * FROM CTE9 c INNER JOIN dbo.Users u ON c.Id = u.Id; |
Run the query, and check the Messages tab:
|
1 2 3 4 5 |
SQL Server parse and compile time: CPU time = 47953 ms, elapsed time = 47980 ms. SQL Server Execution Times: CPU time = 15 ms, elapsed time = 57 ms. |
That complex query plan is hard to build, so it took some time:
The table variable doesn’t have any rows in it, though, so execution time is nearly instantaneous. The hard part here is clearly building the query plan.
But it gets much worse.
Try updating stats while it runs.
In one window, free the plan cache and start rebuilding the indexes on the Users table with online = on so the CTE query can execute:
|
1 2 3 4 |
DBCC FREEPROCCACHE; GO ALTER TABLE dbo.Users REBUILD WITH (ONLINE = ON); GO 5 |
Then in another window, run the CTE query again. Make a pot of coffee or hit the loo, because you’re gonna have some time. Several minutes later, both queries finish, and the output of the CTE’s statistics is pretty bizarre:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
SQL Server parse and compile time: CPU time = 48968 ms, elapsed time = 60903 ms. SQL Server parse and compile time: CPU time = 51157 ms, elapsed time = 63667 ms. SQL Server parse and compile time: CPU time = 56437 ms, elapsed time = 75372 ms. SQL Server parse and compile time: CPU time = 54500 ms, elapsed time = 67981 ms. SQL Server parse and compile time: CPU time = 51078 ms, elapsed time = 63656 ms. SQL Server parse and compile time: CPU time = 48813 ms, elapsed time = 48840 ms. (0 rows affected) SQL Server Execution Times: CPU time = 0 ms, elapsed time = 4 ms. |
What’s happening? Every time the Users rebuild finishes, it’s also updating stats. The query compilation sees those updated stats, and…decides that the plan it just got done building is invalid, so it’d better go try to build another plan! Thus, the repeated messages about parse & compile time.
Yes, I actually hit this problem.
It sounds crazy, but to recreate a client issue, I was loading a 10 billion row table, which takes a while. As it was loading, its statistics were constantly changing, because as it grew, it was constantly hitting the automatic stats updates threshold.
As a result, simple queries with no where clause or order by could finish instantly, but add in even the simplest where clause, and the query would never finish. It was constantly recompiling as more data was loaded.
Shout out to Joe Obbish and Paul White who helped me troubleshoot this problem last year – all credit for solving the mystery goes to them:
To close the loop on this: @SQL_Kiwi and @JoeObbish nailed the root cause analysis. The query is continuously compiling because another session is loading data in the table and changing the statistics. Related reading: https://t.co/wL3IAQQ3Dz
— Brent Ozar (@BrentO) October 6, 2020
19 Comments. Leave new
I actually ran into this issue last week. I was trying to get a few key statistics uptodate as the customer could dump a large amount of orders in the system at any time and we wanted to have the statistics updated at that point to make sure the queries were aware of that.
We overdid it a bit though and kept updating the statistics even when not needed. This caused a few complex queries that normally ran in about 50 milliseconds to take a few seconds as they kept getting compiled. It took a while before I realized what was happening.
very interesting, but what does sql do in 1 minute of compilation time ??? Is it spent on what?
Great question! We cover that in my Fundamentals of Query Tuning and Mastering Query Tuning classes.
…no other spoilers? 🙂
Not for people who aren’t hard-working enough to go click on that course and look at the agenda. Folks too lazy to do that can’t be helped, sadly. They’re doomed to live a life of complete ignorance and darkness.
Sure would suck to be one of those.
Good thing that doesn’t apply to you, right?
Maybe he is from Europe like me. We might still be doomed as well though. 🙂
Nicely done!
mmmh, “do you have your things”?
Where I am, if we put in a job to make the system more efficient – even change the frequency of how often a log backup occurs – there are people who scream that it had not gone a proper Change Management process which can take weeks and is usually stopped by some non-technical numpty.
Wow nice stuff! I love fun, obscure trivia, documenting a situation I’ll probably never run into, because one day or another, I’m sure to run into it 😉 Thanks for sharing that with us!
So, it sounds like have auto update statistics on while loading a large table is a performance problem. Kind of like keeping indexes on the table instead of dropping/creating them.
That’s awesome, what an unusual edge case!
Sounds like SQL Server could have some belt ‘n braces to deal with that, such as a timeout so that if a query has had n number of compilations within x seconds for the same spid then just run with it?
Stu – sure, you could recommend that as an improvement to SQL Server.
Updating statistics is indeed a hit and auto update statistics let’s lazy DBA’s say we have it covered and live with the comments of poor performance instead of understanding what Update Statistics does and what the benefit is. Of course updated statistics have their purpose duh ! But what an excellent real world senarion from Brent. Thank You. Derek
And this topic probably leads to availing of the latest query execution plan. sp_recompile etc.
but can’t we disable the auto-update of the statistics at the table level?
Sure. You have to know to do that, and when, though, and when to enable it again. (That’s well beyond the scope of this post.)
I think Brent is giving us a hint that leaving auto-update of statistics turned off, from start to finish of a jumbo table load, is not always ideal.
I could be wrong.
You are correct and that is my experience and interpretation. Experienced the effect many years ago when SQL Server was processing 900 transactions per second coping with multiple extremely busy production lines in a factory. I suppose the pain experienced due to the performance of out of date statistics made me sit up and try to understand what happens when statistics are being updated. I think there is no golden rule as you need to know you environment and make decisions. Importantly statistics must be updated. How you chose to navigate is the quandry. Still learning this very day many aspects of SQL Server. Derek.