성능분석 10탄 – 쿼리 실행 대기 시간 분석(xevent)

성능분석 10탄 – 쿼리 실행 대기 시간 분석(xevent)

 

• Version : SQL Server 2005, 2008, 2008R2, 2012

 

쿼리 또는 저장프로시저에 대한 가장 좋은 대기 유형 정보는 실행 시간과 IO 정보이다. 이 정보는 확장이벤트(XEvent)를 사용하여 모니터링을 할 수 있다.

다음 스크립트는 Sqlos.wait_info 정보를 캡처하고 특정 실행 세션(SPID)에 대한 확장 이벤트 세션을 필터링하는 확장이벤트 세션 생성 작업이다.

 

create event session session_waits on server add event sqlos.wait_info (WHERE sqlserver.session_id= 54/*execution_spid*/ and duration>0) , add event sqlos.wait_info_external (WHERE sqlserver.session_id = 54/*execution_spid*/ and duration>0) add target package0.asynchronous_file_target (SET filename=N'c:\temp\wait_stats.xel', metadatafile=N'c:\temp\wait_stats.xem'); go   alter event session session_waits on server state= start; go

 

 

 

이벤트 세션을 시작하고 분석할 쿼리나 프로시저를 실행 한다. 그 후 확장 이벤트 서비스를 중지하고 캡처된 데이터를 확인 한다.

alter event session session_waits on server state= stop; go   with x as ( select cast(event_data as xml) as xevent from sys.fn_xe_file_target_read_file ('c:\temp\wait_stats*.xel', 'c:\temp\wait_stats*.xem', null, null)) select * from x; go

 

 

이벤트 세션을 중단하고 캡처된 이벤트를 클릭하면 XML 정보를 확인 할 수 있다.

 

4밀리세컨드의 IX 잠금이 발생하였다. 그리고 작업이 재개 될 때까지 또 다른 2밀리세컨드 보냈다. 다음 스크립트를 이용하ㅕㅁㄴ XML 데이터를 테이블 형식으로 확인할 수 있다.

with x as ( select cast(event_data as xml) as xevent from sys.fn_xe_file_target_read_file ('c:\temp\wait_stats*.xel', 'c:\temp\wait_stats*.xem', null, null)) select xevent.value(N'(/event/data[@name="wait_type"]/text)[1]', 'sysname') as wait_type,     xevent.value(N'(/event/data[@name="duration"]/value)[1]', 'int') as duration,     xevent.value(N'(/event/data[@name="signal_duration"]/value)[1]', 'int') as signal_duration from x;

 

다음 스크립트는 XML의 정보를 대기 유형에 따라 집계한 것이다.

with x as ( select cast(event_data as xml) as xevent from sys.fn_xe_file_target_read_file ('c:\temp\wait_stats*.xel', 'c:\temp\wait_stats*.xem', null, null)), s as (select xevent.value(N'(/event/data[@name="wait_type"]/text)[1]', 'sysname') as wait_type,     xevent.value(N'(/event/data[@name="duration"]/value)[1]', 'int') as duration,     xevent.value(N'(/event/data[@name="signal_duration"]/value)[1]', 'int') as signal_duration from x) select wait_type,     count(*) as count_waits,     sum(duration) as total__duration,     sum(signal_duration) as total_signal_duration,     max(duration) as max_duration,     max(signal_duration) as max_signal_duration from s group by wait_type order by sum(duration) desc

 

 

이 결과를 바탕으로 쿼리가 실행되는 동안 어떤 일이 있었는지를 확인 할 수 있다. 이 로그를 보면 742번의 WRITELOG가 발생하였으며, 12번의 잠금이 발생, 그리고 2개의 PAGELATCH가 발생하였다.

 

 

[참고자료]

http://rusanu.com/2014/02/24/how-to-analyse-sql-server-performance/

 

2014-03-21 / 강성욱 / http://sqlmvp.kr

 

 

SQLSERVER, mssql, SQL튜닝, 강성욱, SQL강좌, DB튜닝, 쿼리튜닝, 데이터베이스튜닝, xevent, wait_type, sql2012, sql2008, sql2008R2, Sqlos.wait_info