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.