Trace-如何跟踪某个Job的开销

1、背景

下面是从以往Profiler收集的跟踪文件中提取Job有关数据

;with cte as(
select b.Name EventClass,TextData,DatabaseName,Duration/1000 Duration_ms
,CPU CPU_ms,Reads,Writes,StartTime,EndTime,HostName,LoginName,ApplicationName
,row_number() over(partition by ApplicationName order by CPU desc) rankid 
from fn_trace_gettable(N'F:TroubleShootingTraceInstanceName_HighCPU40_20160907.trc', 1) a
inner join sys.trace_events b
on a.EventClass=b.trace_event_id
where ApplicationName like '%SQLAgent - TSQL JobStep%'
)
select * from cte where rankid=1
order by CPU_ms desc

View Code

如何快速定位问题语句归属哪个Job？

1.1、关键字匹配

使用TextData中的关键字到msdb.dbo.sysjobsteps中的command中匹配

select sj.name,sjs.command,sjs.step_id 
from msdb.dbo.sysjobs sj
inner join msdb.dbo.sysjobsteps sjs
on sj.job_id=sjs.job_id
where sjs.command like '%FishGameReturnRateStatistics%'

View Code

根据返回的Job名称，结合Job历史记录、问题语句Duration，基本可以定位到确切的Job。
存在问题，如果问题语句是一段很长的SQL，而非存储过程，关键字的划定直接影响定位的命中率，进而影响查找时间。

1.2、Job_id匹配

我们注意看第一张图中的ApplicationName列，SQLAgent - TSQL JobStep (Job 0xCFAF657344E1624E98B1DD4676CC18EC : Step 7)，有点像是某个Job的第7个步骤。会是哪个作业，中间那串"16进制"与Job_id有什么关系？

--补充 16:22 2017/8/9 根据ApplicationName得到作业名称
select job_id,name from msdb.dbo.sysjobs
where job_id=convert(uniqueidentifier,0xCFAF657344E1624E98B1DD4676CC18EC)

View Code

2、ApplicationName与Job_id的关系

为了核查ApplicationName与Job_id的关系，创建一个跟踪，列筛选器添加对TextData筛选，作业运行得到跟踪结果

我们再来看作业的Job_id

将ApplicationName列与Job_id对比
ApplicationName:0x9C91EB5022BD9F4D94FEA58A22571EBA
Job_id:50EB919C-BD22-4D9F-94FE-A58A22571EBA
适当调整样式
ApplicationName:0x-9C91EB50-22BD-9F4D-94FE-A58A22571EBA
Job_id : 50EB919C-BD22-4D9F-94FE-A58A22571EBA
是否发现了什么？在16进制中，每两个进制数字表示一个字节，并且是逆序排列的。
那么16进制的9C91EB50对应的实际是50EB919C；16进制的22BD对应的实际是BD22；16进制的9F4D对应的实际是4D9F。剩下的部分ApplicationName与Job_id是一致的，至于为什么这样保存，暂时没找到相关资料。我也只是通过对比，发现存在这样的现象，并推测ApplicationName与Job_id可以进行互转

use msdb
go
create function [dbo].[JobIdToApplicationName](@job_id varchar(36))
returns varchar(38)
as
begin
    declare @str varchar(38)
    select @str='Job 0x'
    +substring(@job_id,7,2)+substring(@job_id,5,2)+substring(@job_id,3,2)+substring(@job_id,1,2)
    +substring(@job_id,12,2)+substring(@job_id,10,2)
    +substring(@job_id,17,2)+substring(@job_id,15,2)
    +replace(substring(@job_id,20,17),'-','')
    return @str
end
go

View Code

结合msdb.dbo.sysjobs就可得到所有Job对应的ApplicationName

use msdb
go
select name,job_id,[dbo].[JobIdToApplicationName](job_id) SubApplicationName 
from msdb.dbo.sysjobs

View Code

3、回归主题

前两天打算跟踪一个作业执行情况，事先查看作业是直接调用存储过程，而存储过程中还会调用其他的存储过程，类似下面

CREATE PROC pro_Parent
AS
BEGIN
    EXEC pro_sub1
    EXEC pro_sub2
    ...
END
GO

View Code

习惯性的选择RPC:Completed和SQL:BatchCompleted事件，并在列筛选器对TextData应用类似于pro_sub1、pro_sub2(两边需用%)
结果第二天上班，查看跟踪数据时，什么都没有！这是由于自己疏忽，在创建跟踪前还提醒自己要添加SP:Completed事件，最后还是给忘了。又是习惯+疏忽！
我想表达的问题是，如果一个Job调用父存储过程，然后父存储过程中又调用子存储过程，如何在Profiler中只得到此Job相关的父存储过程和子存储过程的消耗情况？添加SP:Completed事件，然后TextData应用类似于各父、子存储过程。如果子存储过程很多呢？这样添加略显笨拙。
如果Job调用的是很长的SQL Batch，如何跟踪这个作业的消耗情况？
想想前面的ApplicationName，我们可以根据Job_id得出Job在Profiler中的ApplicationName列的关键信息。然后针对ApplicationName设置筛选器，不管Job执行什么样的脚本，我们都能方便地获取需要事件的信息。
因此对前两天跟踪Job的那个例子，就可以将下面的SubApplicationName应用于ApplicationName列筛选器，当然还需要加上SP:Completed事件

4、总结

只要有了ApplicationName与Job_id的对应关系，不管我们是要跟踪某个Job执行情况，还是要将Profiler结果定位到具体Job，都十分便捷。