dinsdag 23 april 2013

SQL Server and slow compile times of queries

I posted a message on Google+ on Friday about large compile times of queries on SQL Server.
(to be clear: the execution of the query was fast enough, it was slow only the first time).
I could get my query a lot faster by not using view-in-view-in-view, but I wanted to know why.
Today I found some more detailed information about (slow) compilations of queries.

xperf profiling

First, I found some information about using xperf with SQL Server, to profile the performance. In an old blog post I found an explanation about how to log stack traces with xperf too. This was what I was looking for: using a (free, 64bit) sampling profiler to find out what sqlservr.exe is exactly doing all the time!
(note: xperf.exe is now part of the "Windows Performance Toolkit (WPT)", you have to download the Windows ADK and install only WPT)
However, I got a cryptic error on the server: "xperf: error: NT Kernel Logger: Cannot create a file when that file already exists."
By closing Proces Explorer (which uses ETW events too for timing and performance information) I got it working on my own workstation (I did not want to install the (low level?) WPT on the server :), but xperf should also work by using xcopy?)

Viewing results

The next hurdle was getting my stack traces in the latest xperf (Windows Performance Analyzer). Again some "googling" and I found a newer blog post about xperf. It turned out I had to do the following:
1: load all sybols (takes a while) via the menu Trace -> Load Symbols
2: click on "display graph and table" icon (top right in for example CPU usage view)
3: show "stack" column in detail grid (right click in grid)
Inline afbeelding 1
As you can see, the most time it is busy with the "Optimize" procedure (ironic isn't it? :) ).
(note: 25% cpu is one core at 100% of my quad core pc, so 20% is actually 80% cpu usage)

Optimization phase

Armed with this information I could search further and I found some posts about the optimization phase.
Inside SQL Server: Parse, Compile, and OptimizeThe SQL Server Query Optimizer

Somehow I found a "deep dive" into the Optimizer, including some undocumented trace flags (!) for really low level inner details. Yeah! :)

Too much information to handle for now, but at least (as far as I understand from the internal counters etc) it did not even complete the normalization phase due to too much groups and too large or complex tree. It timed out on "Simplification phase" (see part 2), so it didn't optimize at all? It seems so: the query is executing slower than my one big single select (24s vs 58s of all 30.000 records in a test db). I read somewhere that a view is some kind of a macro that is completely loaded to compile the plan. When you have a lot of "view-in-view-in-view", a lot of "macros" are loaded, which takes then a lot of time to process. It seems even worse: a subselect of the same content of a view is much faster to compile than using or joining the same view.

Remarks and questions

By the way, some remarks of my test:
  • I used a new database with no data in it (so it is probably even slower on big databases with larger statistics?)
  • I also tried to delete all auto generated statistics (and disabling auto generation of statistics) but this didn´t change anything (compilation stayed slow)
  • I also tried all SQL OPTION hints, but again, no effect
Some remaining questions:
  • why do I get a optimization timeout after 7s on my pc but after 15s on (an older, internal virtualized) server and 25s on a customer server?
  • I tested it on SQL Server 2008 R2, how would it perform on SQL Server 2012?
  • Why did we use so much views?
I hope to answer (some of) these question the next time.


Well, the conclusion hasn't changed: do not use many views in views! Or at least be aware of the consequences.

Some final tips