SQL Profile - Duration value more than Profiler run time

19 Aug 2006 3:11 PM

kart

Hi All,

We monitored the event RPC:Completed in SQL Profiler for a web-service call,
which in turn calls an Stored Procedure and the results were strange. The
output came very quick, but the duration value was too high. The actual time
taken by query was in milliseconds, whereas, SQL Profiler show around
8minutes(after converting data from microseconds). So, we decided to monitor
Stored Procedure completed event by executing the stored procedure in Query
Analyzer window of SQL Management Studio and here are the results, which are
again very strange

SQL Profiler Trace Start Time: 11:34
SQL Profiler Trace End Time: 11.36
SP:Completed Event Start Time: 11:34:55:023
SP:Completed Event End Time: 11:34:55:723
Same date for Start and End time.
SP:Completed Duration: 504536789 (microseconds from trace table) = 8mts.
SQL Server version: Microsoft SQL Server 2005 - 9.00.1399.06 (Intel X86)
Oct 14 2005 00:33:37 Copyright (c) 1988-2005 Microsoft Corporation
Enterprise Edition on Windows NT 5.2 (Build 3790: Service Pack 1)

The duration value is really strange to look at. It is more than SQL Trace
start and end time(in SQL Profiler). Is this an issue with the profiler.

19 Aug 2006 4:20 PM

Greg Linwood

Hi kart

There have been issues with Duration for as long as SQLTrace has been in
existance. In cases where I've found it produced inconsistent results (or
even no results) in the past, I've often resorted to doing a datediff
between StartTime / EndTime to get a more reliable value for Duration. This
might be a useful short-term solution for you at the moment.

Regards,
Greg Linwood
SQL Server MVP

Show quote

"kart" <k***@discussions.microsoft.com> wrote in message
news:65C25789-9A24-4624-86F5-92B2BFDC598A@microsoft.com...
> Hi All,
>
> We monitored the event RPC:Completed in SQL Profiler for a web-service
> call,
> which in turn calls an Stored Procedure and the results were strange. The
> output came very quick, but the duration value was too high. The actual
> time
> taken by query was in milliseconds, whereas, SQL Profiler show around
> 8minutes(after converting data from microseconds). So, we decided to
> monitor
> Stored Procedure completed event by executing the stored procedure in
> Query
> Analyzer window of SQL Management Studio and here are the results, which
> are
> again very strange
>
> SQL Profiler Trace Start Time: 11:34
> SQL Profiler Trace End Time: 11.36
> SP:Completed Event Start Time: 11:34:55:023
> SP:Completed Event End Time: 11:34:55:723
> Same date for Start and End time.
> SP:Completed Duration: 504536789 (microseconds from trace table) = 8mts.
> SQL Server version: Microsoft SQL Server 2005 - 9.00.1399.06 (Intel X86)
> Oct 14 2005 00:33:37 Copyright (c) 1988-2005 Microsoft Corporation
> Enterprise Edition on Windows NT 5.2 (Build 3790: Service Pack 1)
>
> The duration value is really strange to look at. It is more than SQL Trace
> start and end time(in SQL Profiler). Is this an issue with the profiler.
>
>

19 Aug 2006 10:38 PM

Erland Sommarskog

kart (k***@discussions.microsoft.com) writes:

> SP:Completed Duration: 504536789 (microseconds from trace table) = 8mts.
> SQL Server version: Microsoft SQL Server 2005 - 9.00.1399.06 (Intel X86)

Not that I know it it helps, but you are running the RTM version of
SQL 2005. You may want to install SP1.

--
Erland Sommarskog, SQL Server MVP, esq***@sommarskog.se

Books Online for SQL Server 2005 at
http://www.microsoft.com/technet/prodtechnol/sql/2005/downloads/books.mspx
Books Online for SQL Server 2000 at
http://www.microsoft.com/sql/prodinfo/previousversions/books.mspx