성능분석 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/
강성욱 / jevida@naver.com
Microsoft SQL Server MVP
Blog : http://sqlmvp.kr
Facebook : http://facebook.com/sqlmvp
