SQL Server Developer Center > SQL Server Forums > SQL Server Database Engine > Duration, starttime and Endtime in profiler...
Ask a questionAsk a question
 

AnswerDuration, starttime and Endtime in profiler...

  • Monday, October 26, 2009 5:37 PMRanga1 Users MedalsUsers MedalsUsers MedalsUsers MedalsUsers Medals
     
    I have a trace file...for one of the sql stmt in a stored procedure, SP:stmtCompleted event the duration column shows 620077 -- meaning 620 seconds, that is more than 10 mins! but the starttime and end endtime are same...so it took no time to execute this sql stmt...why does the duration is off ?

    This is sql 2005.

    Thanks.

Answers

  • Tuesday, October 27, 2009 2:23 AMJustin ShenMSFTUsers MedalsUsers MedalsUsers MedalsUsers MedalsUsers Medals
     Answer

    Could you check errorlog for the same time period and see if there is any error like "time stamp is not synchronized"?
    Duration column uses high resolution CPU time counter and if you are running on a multi-proc machine, the value could be incorrect due to incorrect configuration on hardware.
    Whereas, the starttime and endtime column uses OS level time-counter which only supports milliseconds level tracking but is guranteed to be correct.

    See the following article.
    http://support.microsoft.com/kb/931279

All Replies

  • Monday, October 26, 2009 5:52 PMLekss Users MedalsUsers MedalsUsers MedalsUsers MedalsUsers Medals
     
    Hi Ranga ,

    The duration column is measured in microsecond not milliseconds . so 620077*10^-6 = .62 seconds.
    Now check your start time and endtime and see if the difference is just .62 of a second.

    Although there seems a difference in calculation of starttime and endtime not matching with duration in profiler expllained here http://social.msdn.microsoft.com/forums/en-US/sqldatabaseengine/thread/7fb0a68f-07f5-4da8-a0db-3bb6468daed4/ , i dont think you have had that scenario here . I am not sure if it was fixed in sp1 ,2 or 3 .
    Thanks, Leks
  • Monday, October 26, 2009 6:24 PMRanga1 Users MedalsUsers MedalsUsers MedalsUsers MedalsUsers Medals
     

    Hmmmm...I thought profiler always displays in milliseconds. Only if you set a filter using sp_trace_setfilter, you use microseconds! I guess it was changed in SQL 2005 SP3...I also have SQL 2008 client tools installed.

    Thanks.

  • Monday, October 26, 2009 6:45 PMLekss Users MedalsUsers MedalsUsers MedalsUsers MedalsUsers Medals
     
    Now is the .62 second difference ok  ? Does it match with the duration column ?
    Thanks, Leks
  • Monday, October 26, 2009 7:35 PMRanga1 Users MedalsUsers MedalsUsers MedalsUsers MedalsUsers Medals
     
    nope...the starttime and endtime have it same: 2009-10-26 08:29:43.943...duration is 620077
  • Monday, October 26, 2009 8:09 PMRanga1 Users MedalsUsers MedalsUsers MedalsUsers MedalsUsers Medals
     
    Ok....it is not microseconds, but milliseconds!...In profiler Tools-->Options, if you check show in microseconds, then you see in microseconds, if not it is milliseconds....
  • Tuesday, October 27, 2009 2:23 AMJustin ShenMSFTUsers MedalsUsers MedalsUsers MedalsUsers MedalsUsers Medals
     Answer

    Could you check errorlog for the same time period and see if there is any error like "time stamp is not synchronized"?
    Duration column uses high resolution CPU time counter and if you are running on a multi-proc machine, the value could be incorrect due to incorrect configuration on hardware.
    Whereas, the starttime and endtime column uses OS level time-counter which only supports milliseconds level tracking but is guranteed to be correct.

    See the following article.
    http://support.microsoft.com/kb/931279

  • Wednesday, November 04, 2009 2:18 PMRanga1 Users MedalsUsers MedalsUsers MedalsUsers MedalsUsers Medals
     
    Yes..I see the error message all over the error log...Thanks.