Qx events in the Developer Dashboard
Introduction
What’s one the first things you will turn on when you are troubleshooting performance problems? Right.. the awesomely Developer Dashboard! (honestly, I cannot comprehend on how troubleshooting was done in the 2003/2007 time.. respect! :)
I actually assuming that you know what it is, so I won’t go over what it actually is other than it helps you in finding out if the performance problems are:
- in SharePoint or custom code
- in SQL
- on the client (if the dashboard is saying it’s done within 50ms and your browser (IE + Developer Toolbar or Firefox + Firebug) or Netmon that it is taking +150ms than its something between the WFE and the client..)
Qx events?
While being on-site this week, the first priority was to check for some performance problems they were having on one of their environments. So, first thing I asked was, if they could turn on the Developer Dashboard. When browsing to some sites I indeed noticed the slow performance and to my surprise saw some events that I’ve never seen before in the dashboard. Maybe you also haven’t (or if you were me and try searched for it and found nothing) you’re in luck now ;)
Just to set the right expectation, I’m not talking about Audi’s Q3 or Q5 or even the Q7.. I’m talking about the Q2 and Q3 events that are listed in the screenshot above, 21205ms is quite a long time to be spent in the database right? Luckily, in a strange sort of way, reproducing this was quite easy since every page request resulted in such long running database queries. Therefore, we could setup a SQL Profiler trace to see what was going on behind the scenes.. however, I found nothing in the trace that corresponded to the 20s the developer dashboard was telling me with the Q2 message.
So I fired up the ULSViewer again, this time to check more thoroughly what exactly was happening by using the correlation ID. What I found was the following:
- Last message before the 20s delay : Current user before SqlConnection.Open: Name: DOMAIN\USERNAME SID: S-X-X-XX-XXXXXXXXX-XXXXXXXXX-XXXXXXXX-XXXXX ImpersonationLevel: None
- First message after the 20s delay : System.Data.SqlClient.SqlException: A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
- More detailed message : Failure checking user access permissions for User Profile Application Proxy 'User Profile Service Proxy'. Exception: System.Data.SqlClient.SqlException: A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server)
That’s why we have such slow pages, a request is being made to a SQL Server from a environment which cannot be reached because of VLAN configuration. Since this was a QA farm, it was accidently pointing to a Production farm due to a misconfiguration in the QA farm. Problem fixed ;)
In the meantime, I got word from the one of the developers of the Developer Dashboard (that’s really one of the coolest things of working for Microsoft ;) stating that whenever a ‘Q’ message is listed it is because of the following :
Q stands for query. Sometimes, we know that there has been a SQL query, but don’t want to store the SQL text or callstack. For example, if you have a page with more than 50 SQL queries, that’s your problem. Getting details on the 51st query just isn’t worth the server processing costs.
Plus, we fall to a catch block which omits the detailed logging information if the connection fails.
Conclusion
So there you have it! Once more a proof that the developer dashboard is awesome and the answer to what the Qx messages mean ;)