반응형

성능분석 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

반응형

+ Recent posts