One DBA's Ongoing Search for Clarity in the Middle of Nowhere


*or*

Yet Another Andy Writing About SQL Server

Thursday, April 14, 2016

How Long Did That Job Run?

When you use the msdb tables to try to gather information on your SQL Server Agent jobs, inevitably you will end up in a situation like this:
SELECT TOP 10 
sj.name as JobName
,sjh.run_date as RunDate
,sjh.run_time as RunTime
,sjh.run_duration as Duration
from msdb.dbo.sysjobhistory sjh
join msdb.dbo.sysjobs sj
on sjh.job_id = sj.job_id
where step_id=0
JobName RunDate RunTime Duration
ServerA_RESTORE_FROM_PROD_V2 20140904 222821 4131
ServerA_RESTORE_FROM_PROD_V2 20140904 231032 3055
ServerA_RESTORE_FROM_PROD_V2 20140904 231130 5003
Bloomberg_Pkg 20140904 231233 205
ServerA_RESTORE_FROM_PROD_V2 20140904 231350 2343
DatabaseIntegrityCheck - SYSTEM_DATABASES 20140923 1500 433
DatabaseBackup - SYSTEM_DATABASES - FULL 20140923 10000 23
syspolicy_purge_history 20140923 20000 36
DatabaseBackup - USER_DATABASES - FULL 20140923 40000 2333
DatabaseIntegrityCheck - SYSTEM_DATABASES 20140924 1500 113
So....when did "DatabaseIntegrityCheck - SYSTEM_DATABASES" start? At 1500 - is that 3pm?  You may be able hash out that this translates to 12:15am local time...but what if you want to perform datetime-style math on the RunDate/RunTime?  Sure you can do multiple leaps to say (RunDate>X and RunDate<=Y) AND (RunTime>A and RunTime<=B), but you then need to explicitly format your X, Y, A, and B in the appropriate integer-style format.  Wouldn't it be easier to just be able to datetime math?

The next part is even worse - quick - how long did the first instance of "ServerA_RESTORE_FROM_PROD_V2" run?

4,131 somethings (seconds, ms, etc), right?

http://ct.fra.bz/ol/fz/sw/i51/5/7/25/frabz-no-191096.jpg
In truth, the job ran forty-one minutes and thirty-one seconds.

http://upandhumming.com/wp-content/uploads/2015/11/serious.jpg
Yes, yes I am.  No precision beyond seconds, and no quick way to do math.  if you want to figure out how much longer instance 1 of the job ran than instance 2, you have to do some serious goofiness to figure it out.

Here is the fix for both of these problems!

--

The first item is easy although not directly obvious without a little help from that old standby:

https://imgflip.com/i/12hu6g
(Yes I am that old...)

Microsoft included a system scalar function msdb.dbo.agent_datetime(run_date, run_time) that turns the combination  on run_date and run_time into a datetime:
SELECT TOP 10
sj.name as JobName
,sjh.run_date as RunDate
,sjh.run_time as RunTime
,msdb.dbo.agent_datetime(sjh.run_date,sjh.run_time) as RunDateTime
from msdb.dbo.sysjobhistory sjh
join msdb.dbo.sysjobs sj
on sjh.job_id = sj.job_id
where step_id=0
JobNameRunDateRunTimeRunDateTime
ServerA_RESTORE_FROM_PROD_V220140904222821
09/04/2014 22:28:21
ServerA_RESTORE_FROM_PROD_V220140904231032
09/04/2014 23:10:32
ServerA_RESTORE_FROM_PROD_V220140904231130
09/04/2014 23:11:30
Bloomberg_Pkg20140904231233
09/04/2014 23:12:33
ServerA_RESTORE_FROM_PROD_V220140904231350
09/04/2014 23:13:50
DatabaseIntegrityCheck - SYSTEM_DATABASES201409231500
09/23/2014 00:15:00
DatabaseBackup - SYSTEM_DATABASES - FULL2014092310000
09/23/2014 01:00:00
syspolicy_purge_history2014092320000
09/23/2014 02:00:00
DatabaseBackup - USER_DATABASES - FULL2014092340000
09/23/2014 04:00:00
DatabaseIntegrityCheck - SYSTEM_DATABASES201409241500
09/24/2014 00:15:00
I agree with the author of this post who calls the agent_datetime() function "undocumented" since there wasn't a record of it in Books Online - I checked around and couldn't find any standard documentation of it on MSDN or TechNet.

Now that we have a datetime, we can perform all of the regular datetime manipulation functions such as DATEDIFF() on the values.

--

The second part is a little more obnoxious - there isn't a quick Microsoft function (documented or otherwise) to make the run_duration into a process-ready value.

To hash the run_duration into a useful value I wrote a CASE statement some time ago:
SELECT TOP 10
sj.name as JobName
,CASE len(sjh.run_duration)
WHEN 1 THEN cast('00:00:0'
+ cast(sjh.run_duration as char) as char (8))
WHEN 2 THEN cast('00:00:'
+ cast(sjh.run_duration as char) as char (8))
WHEN 3 THEN cast('00:0'
+ Left(right(sjh.run_duration,3),1)
+':' + right(sjh.run_duration,2) as char (8))
WHEN 4 THEN cast('00:'
+ Left(right(sjh.run_duration,4),2)
+':' + right(sjh.run_duration,2) as char (8))
WHEN 5 THEN cast('0'
+ Left(right(sjh.run_duration,5),1)
+':' + Left(right(sjh.run_duration,4),2)
+':' + right(sjh.run_duration,2) as char (8))
WHEN 6 THEN cast(Left(right(sjh.run_duration,6),2)
+':' + Left(right(sjh.run_duration,4),2)
+':' + right(sjh.run_duration,2) as char (8))
END as 'Duration'

,run_duration
from msdb.dbo.sysjobhistory sjh
join msdb.dbo.sysjobs sj
on sjh.job_id = sj.job_id
where step_id=0
JobName Duration run_duration
ServerA_RESTORE_FROM_PROD_V2 00:41:31 4131
ServerA_RESTORE_FROM_PROD_V2 00:00:03 3
ServerA_RESTORE_FROM_PROD_V2 00:00:05 5
Bloomberg_Pkg 00:00:02 2
ServerA_RESTORE_FROM_PROD_V2 00:00:02 2
DatabaseIntegrityCheck - SYSTEM_DATABASES 00:00:43 43
DatabaseBackup - SYSTEM_DATABASES - FULL 00:00:02 2
syspolicy_purge_history 00:00:36 36
DatabaseBackup - USER_DATABASES - FULL 00:00:02 2
DatabaseIntegrityCheck - SYSTEM_DATABASES 00:00:11 11

Interestingly I recently discovered a more elegant solution (while looking for a answer to a different problem) that utilizes the STUFF() function.  Look at this forum post on SQLServerCentral.  The fourth item down from "Mudluck" is almost exactly the same as my CASE statement above, but look at the reply below it from "JG-324908":
SELECT stuff(stuff(replace(str(run_duration,6,0),' ','0'),3,0,':'),6,0,':') FROM sysJobHist
Sure enough, running this STUFF() code results in the same output as the much more complicated CASE statement above.  JG notes that he/she found it in a forum post somewhere and I dug around a little to see if I could find the original author without any luck :(

--

As with many other bits of code, I keep these things in a big NotePad file of useful code snippets (some people like OneNote instead, and there are dozens of choices - use the one you normally prefer) so that I can quickly reference them when needed.  I always note the website or forum post where I found the code if I didnt create it myself as well as the original author.  This lets me give credit where credit is due when showing the code to others, but it also gives me an idea of someone to approach in the future if I have a question about a similar topic.

It was especially interesting to find the STUFF() code because STUFF() isn't a function I often use, and in this case it was perfect.

--

Hope this helps!


2 comments:

  1. I've been using this for years. Works pretty well:
    http://www.sqlservercentral.com/scripts/Miscellaneous/30685/

    ReplyDelete
  2. I prefer to convert the duration directly to seconds as an integer. I find it more convenient for sorts and other functions (Sum, Avg, etc.).
    [Duration sec] = (jh.run_duration % 100) -- Seconds
    + 60 * ((jh.run_duration /100) % 100) -- + minutes to seconds
    + 3600 * ((jh.run_duration / 10000) % 100) -- + Hours to seconds

    ReplyDelete