Wednesday, August 26, 2009

Duration in RPC:Completed is Misleading

I discovered something today while troubleshooting a long running query today. We have a specific dialog in our application which in a specific case takes 60 seconds to open up. I fire up SQL Profiler and click run just to see the standard events and verify if this a DB issue or not.

I find that there is a specific query which does take 60 seconds to run according to the RPC:Completed event (We are using SQL Server 2005). So I pull that query out and run it inside of SSMS, it completes in under a second. These are the issues I hate having to troubleshoot. So the first thing was to rule out our web application, so I create a little .net windows form app and I basically run this:


sqlCmd.Connection.Open();
using (var reader = sqlCmd.ExecuteReader())
{
    int i = 0;
    while (reader.Read())
    {
        i++;
    }

    MessageBox.Show(i.ToString());
}



The query runs fine no issue. Now we are actually using nHibernate so I wanted to simulate us processing the result set. I add a small Thread.Sleep(5) (my result set has 1500 items in it so a small sleep duration is plenty). I run the query and wait about eight seconds.

Then I go and look at SQL Profiler RPC:Completed (And Stmt:Completed events). The duration for the events is 8 seconds. Now I am asking myself if I opened a ticket with Microsoft burned a support incident for an nHibernate issue or not.

The moral of the story? Well don't always trust what you think the tool is measuring. And if your interested, when I ran my queries loading the entities through nHibernate with the windows form, the query again completed extremly fast. So I am still hunting this one down.

Update

I found and resolved the issue. It wasn't an issue with SQL but a configuration issue which caused the system to try and log to an invalid file thousands of times which slowed the system down.

This is very eye-opening as one of my fundamental assumptions about SQL Profiler and how to interpret the results has been crushed.

2 comments:

John said...

I Installed SQL server 2005, installation completed with out any warnings.
but when trying to configure reporting services it is not configured and throwing error message as create virtual directory.so I am in trouble.
dsi xl

Jack said...

Can you tell more about the "Files Checked"?

I have a select/insert process that is happening over and over - takes .8ms each - but every 500 or so statements the PRC:completed jumps to 1 second for a statement and the sp:completed remains at .8ms.