Executing Query Problem - CPU Time vs Total Elapsed Time

• Brandie Tarvin

  SSC Guru

  Points: 173107

  More actions

  March 22, 2012 at 5:44 am

  #253528

  This is probably a simple question, but I am not awake yet and my mind is going in fifty different directions right now.

  I suspect I have a job that's been executing since yesterday. The history shows it executed last at 9:00 a.m. yesterday, and that it is due to execute this morning at 6:00 a.m. (it's past 6 a.m. as I write this and it's still executing). I ran sp_who2 (our wonderful undocumented function) on my server to check a SPID. I wanted to see how long it had been executing. This is what I came up with:

  SPID Status Login HostName BlkBy DBName Command CPUTime DiskIO LastBatch ProgramName SPID REQUESTID

  87 SUSPENDED <ServiceAcct> <Server> . <DBName> RESTORE DATABASE 63 25 03/22 06:00:02 SQLAgent - TSQL JobStep (Job 0x1DF8112660A8454D8040FF40B607DF10 : Step 1) 87 0

  87 RUNNABLE <ServiceAcct> <Server> . <DBName> RESTORE DATABASE 0 003/22 06:00:02 SQLAgent - TSQL JobStep (Job 0x1DF8112660A8454D8040FF40B607DF10 : Step 1) 87 0

  Now, the above all looks wrong to me. CPUTime at 63? DiskIO at 25? and then at 0 and 0 for the next SPID, same job? There's something hokey, but I can't remember how to interpret CPUTime. So I went a googling and couldn't find the definitions of the sp_who2, but did find a DMV from this site http://sqlserver-qa.net/blogs/t-sql/archive/2008/07/30/4671.aspx. Okay, so I'm too tired to actually parse the entire thing in my head right now, but total elapsed time seems self explanitory.

  select r.session_id

  ,status

  ,substring(qt.text,r.statement_start_offset/2,

  (case when r.statement_end_offset = -1

  then len(convert(nvarchar(max), qt.text)) * 2

  else r.statement_end_offset end - r.statement_start_offset)/2)

  as query_text --- this is the statement executing right now

  ,qt.dbid

  ,qt.objectid

  ,r.cpu_time

  ,r.total_elapsed_time

  ,r.reads

  ,r.writes

  ,r.logical_reads

  ,r.scheduler_id

  from sys.dm_exec_requests r

  cross apply sys.dm_exec_sql_text(sql_handle) as qt

  where r.session_id > 50

  order by r.scheduler_id, r.status, r.session_id

  Here are my results:

  session_id status query_text dbid objectid cpu_time total_elapsed_time reads writes logical_reads scheduler_id

  87 suspended RESTORE DATABASE <other TSQL> NULL NULL 63 5329553 1 24 3971 4

  102 suspended WAITFOR DELAY '00:00:10' NULL NULL 1069106 -1202519724 175439 1308458 100365903 7

  So, apparently my job has been running longer than expected (5329553), but I'm unsure of how to translate this into hours and minutes to verify. Also, what's with the negative time on the other SPID? (-1202519724)? That one has me completely confused. How can a job reverse execute?

  Does anyone have an insight that could help?

  Brandie Tarvin, MCITP Database AdministratorLiveJournal Blog: http://brandietarvin.livejournal.com/[/url]On LinkedIn!, Google+, and Twitter.Freelance Writer: ShadowrunLatchkeys: Nevermore, Latchkeys: The Bootleg War, and Latchkeys: Roscoes in the Night are now available on Nook and Kindle.

• patrickmcginnis59

  SSCertifiable

  Points: 6483

  More actions

  March 22, 2012 at 8:51 am

  #1462770

  I think time is in milliseconds, and it takes 24 days to use 2 billion milliseconds sending it into negativeland, and 63 milliseconds of cpu time isn't much. Maybe a stalled process that ran 63 milliseconds then stuck?

  Just a wild guess for fun!

  In any case you can google the tables you're querying for field definitions.

  http://msdn.microsoft.com/en-us/library/ms177648.aspx for instance.