SQL SERVER:事件探查器的使用
最近因为在近一期的测试结果中,发现在数据库竟然存在此死锁症状,于是上头下达命令,必须把死锁原因找出来,也就是执行的SQL语句定位出来.
以前对于ORACLE的定位倒是做过,但SQL SERVER没有做过.
在同事的建议下,开始的事件探查器的使用过程.
第一步:下载RML工具,地址直接去微软的官方网站下载,1MB多一点.因为事件探测器不能看到标准的SQL语句,所以需要RML来转换.
第二步:安装好后,直接新建一空的DB 没有多mydb,并且新建存储过程如下:
Create procedure usp_GetAccessPattern
@duration_filter int=-1 --传入的参数,可以按照语句执行的时间过滤统计
as begin
@duration_filter int=-1 --传入的参数,可以按照语句执行的时间过滤统计
as begin
/*首先得到全部语句的性能数据的总和*/
declare @sum_total float,@sum_cpu float,@sum_reads float,@sum_duration float,@sum_writes float
select @sum_total=count(*)*0.01,--这是所有语句的总数。
@sum_cpu=sum(cpu)*0.01, --这是所有语句耗费的CPU时间
@sum_reads=sum(reads)*0.01, --这是所有语句耗费的Reads数目,8K为单位。
@sum_writes=sum(writes)*0.01,--这是所有语句耗费的Writes数目,8K为单位。
@sum_duration=sum(duration)*0.01--这是所有语句的执行时间总和。
from tblBatches --这是Read80Trace产生的表,包括了Trace文件中所有的语句。
where duration>=@duration_filter --是否按照执行时间过滤
declare @sum_total float,@sum_cpu float,@sum_reads float,@sum_duration float,@sum_writes float
select @sum_total=count(*)*0.01,--这是所有语句的总数。
@sum_cpu=sum(cpu)*0.01, --这是所有语句耗费的CPU时间
@sum_reads=sum(reads)*0.01, --这是所有语句耗费的Reads数目,8K为单位。
@sum_writes=sum(writes)*0.01,--这是所有语句耗费的Writes数目,8K为单位。
@sum_duration=sum(duration)*0.01--这是所有语句的执行时间总和。
from tblBatches --这是Read80Trace产生的表,包括了Trace文件中所有的语句。
where duration>=@duration_filter --是否按照执行时间过滤
/*然后进行Group by,得到某类语句占用的比例*/
Select ltrim(str(count(*))) exec_stats,''+ str(count(*)/@sum_total,4,1)+'%' ExecRatio,
ltrim(str(sum(cpu)))+' : '++ltrim(str(avg(cpu))) cpu_stats,''+str(sum(cpu)/@sum_cpu,4,1)+'%' CpuRatio,
ltrim(str(sum(reads) ))+' : '+ltrim(str(avg(reads) )) reads_stats,''+str(sum(reads)/@sum_reads,4,1) +'%' ReadsRatio ,
--ltrim(str(sum(writes) ))+' : '+ltrim(str(avg(writes) )) --writes_stats,''+str(sum(writes)/@sum_writes,4,1) +'%)',
ltrim(str(sum(duration) ))+' : '+ltrim(str(avg(duration))) duration_stats,''+str(sum(duration)/@sum_duration,4,1)+'%' DurRatio ,
textdata,count(*)/@sum_total tp,sum(cpu)/@sum_cpu cp,sum(reads)/@sum_reads rp,sum(duration)/@sum_duration dp
into #queries_staticstics from
/* tblUniqueBatches表中存放了所有标准化的语句。*/
(select reads,cpu,duration,writes,convert(varchar(2000),NormText)textdata from tblBatches
inner join tblUniqueBatches on tblBatches.HashId=tblUniqueBatches.hashid where duration>@duration_filter
) B group by textdata --这个group by很重要,它对语句进行归类统计。
print 'Top 10 order by cpu+reads+duration'
select top 10 * from #queries_staticstics order by cp+rp+dp desc
print 'Top 10 order by cpu'
select top 10 * from #queries_staticstics order by cp desc
print 'Top 10 order by reads'
select top 10 * from #queries_staticstics order by rp desc
print 'Top 10 order by duration'
select top 10 * from #queries_staticstics order by dp desc
print 'Top 10 order by batches'
select top 10 * from #queries_staticstics order by tp desc
Select ltrim(str(count(*))) exec_stats,''+ str(count(*)/@sum_total,4,1)+'%' ExecRatio,
ltrim(str(sum(cpu)))+' : '++ltrim(str(avg(cpu))) cpu_stats,''+str(sum(cpu)/@sum_cpu,4,1)+'%' CpuRatio,
ltrim(str(sum(reads) ))+' : '+ltrim(str(avg(reads) )) reads_stats,''+str(sum(reads)/@sum_reads,4,1) +'%' ReadsRatio ,
--ltrim(str(sum(writes) ))+' : '+ltrim(str(avg(writes) )) --writes_stats,''+str(sum(writes)/@sum_writes,4,1) +'%)',
ltrim(str(sum(duration) ))+' : '+ltrim(str(avg(duration))) duration_stats,''+str(sum(duration)/@sum_duration,4,1)+'%' DurRatio ,
textdata,count(*)/@sum_total tp,sum(cpu)/@sum_cpu cp,sum(reads)/@sum_reads rp,sum(duration)/@sum_duration dp
into #queries_staticstics from
/* tblUniqueBatches表中存放了所有标准化的语句。*/
(select reads,cpu,duration,writes,convert(varchar(2000),NormText)textdata from tblBatches
inner join tblUniqueBatches on tblBatches.HashId=tblUniqueBatches.hashid where duration>@duration_filter
) B group by textdata --这个group by很重要,它对语句进行归类统计。
print 'Top 10 order by cpu+reads+duration'
select top 10 * from #queries_staticstics order by cp+rp+dp desc
print 'Top 10 order by cpu'
select top 10 * from #queries_staticstics order by cp desc
print 'Top 10 order by reads'
select top 10 * from #queries_staticstics order by rp desc
print 'Top 10 order by duration'
select top 10 * from #queries_staticstics order by dp desc
print 'Top 10 order by batches'
select top 10 * from #queries_staticstics order by tp desc
End
第三步:基本步骤已经完成,在开始菜单中打开事件探查器,新建一个TRACE
使用默认模板,并另存为trc文件夹,选择你监听的事件,点击运行,运行完后,直接在CMD里面运行命令:
Read80trace -f -dmydb -Id:\test\aaa.trc mydb:databasename,aaa.trc:另存为文件名.
碰到错误信息:
C:\Program Files\rml>Read80trace -f -dmydb -ID:\eip_320.trc
Output path was not specified; defaulting to C:\Program Files\rml\output
10/19/07 11:18:54 -----------------------------------------------------
10/19/07 11:18:54 Read80Trace version 8.10.0010
10/19/07 11:18:54 -f
10/19/07 11:18:54 -dmydb
10/19/07 11:18:54 -ID:\eip_320.trc
10/19/07 11:18:54 Establishing database connections:
10/19/07 11:18:54 Server: (local)
10/19/07 11:18:54 Database: mydb
10/19/07 11:18:54 Authentication: Windows
10/19/07 11:18:57 Processing: D:\eip_320.trc
10/19/07 11:18:57 WARNING: The following trace events were not captured: SQL:Bat
chStarting, SP:StmtStarting, SP:StmtCompleted, Showplan Statistics. Review the h
elp file to ensure that you have collected the appropriate set of events and col
umns for your intended analysis.
10/19/07 11:18:57 ERROR: Event 10 does not contain the following required column
(s): 15
10/19/07 11:18:57 WARNING: Event 10 does not contain the following recommended c
olumn(s): 3
10/19/07 11:18:57 WARNING: Event 11 does not contain the following recommended c
olumn(s): 3
10/19/07 11:18:57 ERROR: Event 12 does not contain the following required column
(s): 15
10/19/07 11:18:57 WARNING: Event 12 does not contain the following recommended c
olumn(s): 3
10/19/07 11:18:57 ERROR: Event 14 does not contain the following required column
(s): 15
10/19/07 11:18:57 ERROR: Event 15 does not contain the following required column
(s): 15
10/19/07 11:18:57 ERROR: Event 17 does not contain the following required column
(s): 15
10/19/07 11:18:57 ERROR: Performance analysis has been disabled because one or m
ore events is missing required columns. Consult the help file for the recommende
d set of trace events and necessary columns.
10/19/07 11:18:57 Reads completed - Global Error Status 120
10/19/07 11:18:58 READER: Total Read Count: 5 Read Stall Count: 1 accounting for
16 ms in reader thread
10/19/07 11:18:58 Signaling all workers to complete
10/19/07 11:18:58 Handling final IOs and closing open files
10/19/07 11:18:58 Flushing and Compressing SPID Files
10/19/07 11:18:58 Total Events Processed: 0
Output path was not specified; defaulting to C:\Program Files\rml\output
10/19/07 11:18:54 -----------------------------------------------------
10/19/07 11:18:54 Read80Trace version 8.10.0010
10/19/07 11:18:54 -f
10/19/07 11:18:54 -dmydb
10/19/07 11:18:54 -ID:\eip_320.trc
10/19/07 11:18:54 Establishing database connections:
10/19/07 11:18:54 Server: (local)
10/19/07 11:18:54 Database: mydb
10/19/07 11:18:54 Authentication: Windows
10/19/07 11:18:57 Processing: D:\eip_320.trc
10/19/07 11:18:57 WARNING: The following trace events were not captured: SQL:Bat
chStarting, SP:StmtStarting, SP:StmtCompleted, Showplan Statistics. Review the h
elp file to ensure that you have collected the appropriate set of events and col
umns for your intended analysis.
10/19/07 11:18:57 ERROR: Event 10 does not contain the following required column
(s): 15
10/19/07 11:18:57 WARNING: Event 10 does not contain the following recommended c
olumn(s): 3
10/19/07 11:18:57 WARNING: Event 11 does not contain the following recommended c
olumn(s): 3
10/19/07 11:18:57 ERROR: Event 12 does not contain the following required column
(s): 15
10/19/07 11:18:57 WARNING: Event 12 does not contain the following recommended c
olumn(s): 3
10/19/07 11:18:57 ERROR: Event 14 does not contain the following required column
(s): 15
10/19/07 11:18:57 ERROR: Event 15 does not contain the following required column
(s): 15
10/19/07 11:18:57 ERROR: Event 17 does not contain the following required column
(s): 15
10/19/07 11:18:57 ERROR: Performance analysis has been disabled because one or m
ore events is missing required columns. Consult the help file for the recommende
d set of trace events and necessary columns.
10/19/07 11:18:57 Reads completed - Global Error Status 120
10/19/07 11:18:58 READER: Total Read Count: 5 Read Stall Count: 1 accounting for
16 ms in reader thread
10/19/07 11:18:58 Signaling all workers to complete
10/19/07 11:18:58 Handling final IOs and closing open files
10/19/07 11:18:58 Flushing and Compressing SPID Files
10/19/07 11:18:58 Total Events Processed: 0
错误信息意思就是有事件没有监测到,所以不能导入数据成功,字段不匹配.根据错误信息在事件监测里面添加:
SQL:Bat
chStarting, SP:StmtStarting, SP:StmtCompleted, Showplan Statistics
chStarting, SP:StmtStarting, SP:StmtCompleted, Showplan Statistics
再一次运行.
错误信息如下:
10/19/07 15:59:53 ERROR: Event 10 does not contain the following required column(s): 15
10/19/07 15:59:53 WARNING: Event 10 does not contain the following recommended column(s): 3
10/19/07 15:59:53 WARNING: Event 11 does not contain the following recommended column(s): 3
10/19/07 15:59:53 ERROR: Event 12 does not contain the following required column(s): 15
10/19/07 15:59:53 WARNING: Event 12 does not contain the following recommended column(s): 3
10/19/07 15:59:53 WARNING: Event 13 does not contain the following recommended column(s): 3
10/19/07 15:59:53 ERROR: Event 14 does not contain the following required column(s): 15
10/19/07 15:59:53 ERROR: Event 15 does not contain the following required column(s): 15
10/19/07 15:59:53 ERROR: Event 17 does not contain the following required column(s): 15
10/19/07 15:59:53 WARNING: Statement level analysis is disabled because the SP:StmtStarting/SP:StmtCompleted event(s) d
not contain the following required columns: 22, 29
10/19/07 15:59:53 WARNING: Event 45 does not contain the following recommended column(s): 3, 25
10/19/07 15:59:53 ERROR: Performance analysis has been disabled because one or more events is missing required columns.
Consult the help file for the recommended set of trace events and necessary columns.
10/19/07 15:59:53 WARNING: Event 10 does not contain the following recommended column(s): 3
10/19/07 15:59:53 WARNING: Event 11 does not contain the following recommended column(s): 3
10/19/07 15:59:53 ERROR: Event 12 does not contain the following required column(s): 15
10/19/07 15:59:53 WARNING: Event 12 does not contain the following recommended column(s): 3
10/19/07 15:59:53 WARNING: Event 13 does not contain the following recommended column(s): 3
10/19/07 15:59:53 ERROR: Event 14 does not contain the following required column(s): 15
10/19/07 15:59:53 ERROR: Event 15 does not contain the following required column(s): 15
10/19/07 15:59:53 ERROR: Event 17 does not contain the following required column(s): 15
10/19/07 15:59:53 WARNING: Statement level analysis is disabled because the SP:StmtStarting/SP:StmtCompleted event(s) d
not contain the following required columns: 22, 29
10/19/07 15:59:53 WARNING: Event 45 does not contain the following recommended column(s): 3, 25
10/19/07 15:59:53 ERROR: Performance analysis has been disabled because one or more events is missing required columns.
Consult the help file for the recommended set of trace events and necessary columns.
这个错误是因为监测的数据列没有添加进来导致的.如果怕嫌麻烦的话,直接把数据列全部添加进来.再次运行:
C:\Program Files\rml>Read80trace -f -dmydb -Id:\test\aaa.trc
Output path was not specified; defaulting to C:\Program Files\rml\output
10/19/07 16:13:19 -----------------------------------------------------
10/19/07 16:13:19 Read80Trace version 8.10.0010
10/19/07 16:13:19 -f
10/19/07 16:13:19 -dmydb
10/19/07 16:13:19 -Id:\test\aaa.trc
10/19/07 16:13:19 Establishing database connections:
10/19/07 16:13:19 Server: (local)
10/19/07 16:13:19 Database: mydb
10/19/07 16:13:19 Authentication: Windows
10/19/07 16:13:20 Processing: d:\test\aaa.trc
10/19/07 16:13:20 Processing: d:\test\aaa_1.trc
10/19/07 16:13:20 Processing: d:\test\aaa_2.trc
10/19/07 16:13:20 Processing: d:\test\aaa_3.trc
10/19/07 16:13:21 Processing: d:\test\aaa_4.trc
10/19/07 16:13:21 Processing: d:\test\aaa_5.trc
10/19/07 16:13:21 Processing: d:\test\aaa_6.trc
10/19/07 16:13:21 Events Read/Processed: 50000/11764 EPS: 50000/11764
10/19/07 16:13:22 Processing: d:\test\aaa_7.trc
10/19/07 16:13:22 Processing: d:\test\aaa_8.trc
10/19/07 16:13:22 Processing: d:\test\aaa_9.trc
10/19/07 16:13:23 Processing: d:\test\aaa_10.trc
10/19/07 16:13:25 Processing: d:\test\aaa_11.trc
10/19/07 16:13:25 Processing: d:\test\aaa_12.trc
10/19/07 16:13:25 Events Read/Processed: 100000/57561 EPS: 20000/11512
10/19/07 16:13:25 Processing: d:\test\aaa_13.trc
10/19/07 16:13:25 Processing: d:\test\aaa_14.trc
10/19/07 16:13:26 Processing: d:\test\aaa_15.trc
10/19/07 16:13:26 Processing: d:\test\aaa_16.trc
10/19/07 16:13:27 Reads completed - Global Error Status 0
10/19/07 16:13:31 READER: Total Read Count: 701 Read Stall Count: 45 accounting for 422 ms in reader thread
10/19/07 16:13:31 Signaling all workers to complete
10/19/07 16:13:31 Handling final IOs and closing open files
10/19/07 16:13:31 Flushing and Compressing SPID Files
10/19/07 16:13:31 Total Events Processed: 133899
10/19/07 16:13:31 Table dbo.tblUniqueBatches: loaded ~15 rows
10/19/07 16:13:31 Table dbo.tblUniqueStatements: loaded ~55 rows
10/19/07 16:13:31 Table dbo.tblUniquePlans: loaded ~51 rows
10/19/07 16:13:31 Table dbo.tblUniquePlanRows: loaded ~2707 rows
10/19/07 16:13:31 Table dbo.tblBatches: loaded ~3398 rows
10/19/07 16:13:31 Table dbo.tblStatements: loaded ~2200 rows
10/19/07 16:13:31 Table dbo.tblPlans: loaded ~1159 rows
10/19/07 16:13:31 Table dbo.tblPlanRows: loaded ~12106 rows
10/19/07 16:13:31 Table dbo.tblInterestingEvents: loaded ~0 rows
10/19/07 16:13:31 Table dbo.tblConnections: loaded ~7 rows
10/19/07 16:13:31 Indexing tables...
10/19/07 16:13:32 Doing post-load data cleanup...
10/19/07 16:13:32
10/19/07 16:13:32 Dumping error record 1 of 4:
10/19/07 16:13:32 --------------------------------------------------------------------------
10/19/07 16:13:32 Description =
10/19/07 16:13:32 Source = Microsoft OLE DB Provider for SQL Server
10/19/07 16:13:32 ERRORINFO.hrError = 0x80004005
10/19/07 16:13:32 ERRORINFO.dwMinor = 3621
10/19/07 16:13:32 ERRORINFO.clsid = {0C7FF16C-38E3-11D0-97AB-00C04FC2AD98}
10/19/07 16:13:32 SQL State = 01000
10/19/07 16:13:32 Native Error = 3621
10/19/07 16:13:32
Output path was not specified; defaulting to C:\Program Files\rml\output
10/19/07 16:13:19 -----------------------------------------------------
10/19/07 16:13:19 Read80Trace version 8.10.0010
10/19/07 16:13:19 -f
10/19/07 16:13:19 -dmydb
10/19/07 16:13:19 -Id:\test\aaa.trc
10/19/07 16:13:19 Establishing database connections:
10/19/07 16:13:19 Server: (local)
10/19/07 16:13:19 Database: mydb
10/19/07 16:13:19 Authentication: Windows
10/19/07 16:13:20 Processing: d:\test\aaa.trc
10/19/07 16:13:20 Processing: d:\test\aaa_1.trc
10/19/07 16:13:20 Processing: d:\test\aaa_2.trc
10/19/07 16:13:20 Processing: d:\test\aaa_3.trc
10/19/07 16:13:21 Processing: d:\test\aaa_4.trc
10/19/07 16:13:21 Processing: d:\test\aaa_5.trc
10/19/07 16:13:21 Processing: d:\test\aaa_6.trc
10/19/07 16:13:21 Events Read/Processed: 50000/11764 EPS: 50000/11764
10/19/07 16:13:22 Processing: d:\test\aaa_7.trc
10/19/07 16:13:22 Processing: d:\test\aaa_8.trc
10/19/07 16:13:22 Processing: d:\test\aaa_9.trc
10/19/07 16:13:23 Processing: d:\test\aaa_10.trc
10/19/07 16:13:25 Processing: d:\test\aaa_11.trc
10/19/07 16:13:25 Processing: d:\test\aaa_12.trc
10/19/07 16:13:25 Events Read/Processed: 100000/57561 EPS: 20000/11512
10/19/07 16:13:25 Processing: d:\test\aaa_13.trc
10/19/07 16:13:25 Processing: d:\test\aaa_14.trc
10/19/07 16:13:26 Processing: d:\test\aaa_15.trc
10/19/07 16:13:26 Processing: d:\test\aaa_16.trc
10/19/07 16:13:27 Reads completed - Global Error Status 0
10/19/07 16:13:31 READER: Total Read Count: 701 Read Stall Count: 45 accounting for 422 ms in reader thread
10/19/07 16:13:31 Signaling all workers to complete
10/19/07 16:13:31 Handling final IOs and closing open files
10/19/07 16:13:31 Flushing and Compressing SPID Files
10/19/07 16:13:31 Total Events Processed: 133899
10/19/07 16:13:31 Table dbo.tblUniqueBatches: loaded ~15 rows
10/19/07 16:13:31 Table dbo.tblUniqueStatements: loaded ~55 rows
10/19/07 16:13:31 Table dbo.tblUniquePlans: loaded ~51 rows
10/19/07 16:13:31 Table dbo.tblUniquePlanRows: loaded ~2707 rows
10/19/07 16:13:31 Table dbo.tblBatches: loaded ~3398 rows
10/19/07 16:13:31 Table dbo.tblStatements: loaded ~2200 rows
10/19/07 16:13:31 Table dbo.tblPlans: loaded ~1159 rows
10/19/07 16:13:31 Table dbo.tblPlanRows: loaded ~12106 rows
10/19/07 16:13:31 Table dbo.tblInterestingEvents: loaded ~0 rows
10/19/07 16:13:31 Table dbo.tblConnections: loaded ~7 rows
10/19/07 16:13:31 Indexing tables...
10/19/07 16:13:32 Doing post-load data cleanup...
10/19/07 16:13:32
10/19/07 16:13:32 Dumping error record 1 of 4:
10/19/07 16:13:32 --------------------------------------------------------------------------
10/19/07 16:13:32 Description =
10/19/07 16:13:32 Source = Microsoft OLE DB Provider for SQL Server
10/19/07 16:13:32 ERRORINFO.hrError = 0x80004005
10/19/07 16:13:32 ERRORINFO.dwMinor = 3621
10/19/07 16:13:32 ERRORINFO.clsid = {0C7FF16C-38E3-11D0-97AB-00C04FC2AD98}
10/19/07 16:13:32 SQL State = 01000
10/19/07 16:13:32 Native Error = 3621
10/19/07 16:13:32
10/19/07 16:13:32
10/19/07 16:13:32 Dumping error record 4 of 4:
10/19/07 16:13:32 --------------------------------------------------------------------------
10/19/07 16:13:32 Description =
10/19/07 16:13:32 Source = Microsoft OLE DB Provider for SQL Server
10/19/07 16:13:32 ERRORINFO.hrError = 0x80004005
10/19/07 16:13:32 ERRORINFO.dwMinor = 512
10/19/07 16:13:32 ERRORINFO.clsid = {0C7FF16C-38E3-11D0-97AB-00C04FC2AD98}
10/19/07 16:13:32 SQL State = 21000
10/19/07 16:13:32 Native Error = 512
10/19/07 16:13:32 Computing partial aggregates...
10/19/07 16:13:32 Exporting analysis data...
10/19/07 16:13:34 Data load completed.
10/19/07 16:13:35 In the future, analysis results are available by opening "C:\Program Files\rml\output\index.htm" with
Internet Explorer.
10/19/07 16:13:32 Dumping error record 4 of 4:
10/19/07 16:13:32 --------------------------------------------------------------------------
10/19/07 16:13:32 Description =
10/19/07 16:13:32 Source = Microsoft OLE DB Provider for SQL Server
10/19/07 16:13:32 ERRORINFO.hrError = 0x80004005
10/19/07 16:13:32 ERRORINFO.dwMinor = 512
10/19/07 16:13:32 ERRORINFO.clsid = {0C7FF16C-38E3-11D0-97AB-00C04FC2AD98}
10/19/07 16:13:32 SQL State = 21000
10/19/07 16:13:32 Native Error = 512
10/19/07 16:13:32 Computing partial aggregates...
10/19/07 16:13:32 Exporting analysis data...
10/19/07 16:13:34 Data load completed.
10/19/07 16:13:35 In the future, analysis results are available by opening "C:\Program Files\rml\output\index.htm" with
Internet Explorer.
好啦,执行成功啦.数据导入到数据库啦.直接运行刚才的存储过程;
use mydb
exec 存储过程名
结果出来啦.