SQL Server 확장이벤트(XEvent)

주말이 지나고 또 다른 한주가 시작할 무렵 옆에 있는 김군이 나에게 SQL Server 2008 기능중에 XEvent라는 것을 들어 보았냐고 했다. 나도 아직 보지 못한것, 듣지 못한것도 많기에 XEvent가 무엇이냐? 라고 물었고 옆에 있는 김군은 주말에 Sqler.pe.kr 스터디에서 보고 듣은 것을 간략하게 이야기 해 주었다.

이야기인 즉, 간단한 예를 들어 Blocking이나 DealLock이나 Wait같은 것들이나 또는 Stored procedur를 누가 실행시켰나 또는 sys.dm_db_index_physical_stats DMV를 주기적으로 모니터링 하지 않아도 성능을 갉아먹는 조각화를 유발하는 인덱스를 찾아 내거나 등등 어떠한 이벤트를 추적하거나 문제해결을 위해 이전의 매커니즘(DMV 또는 SQL Profiler)을 사용하는것 보다 SQL Server 2008의 확장이벤트(XEvent)을 활용하는게 성능면에서도 좋고, 더 많은 정보를 얻을 수 있어서 좋다고 관련 기술문서에는 나와 있다. 김군이 간단하게 보여준것은 어떠한 프로시져에 확장이벤트를 걸어놓고 그 프로시져를 실행시켰을 때, 확장이벤트에 누가 실행시켰고, 언제 실행시켰는지에 대한 정보가 남도록 하는 것이였다.

일딴, 확장 이벤트는 활성화는 다음과 같은 순서를 따른다.

1. CREATE EVENT SESSION 으로 이벤트 세션을 만든다.
2. ALTER EVENT SESSION 으로 해당 세션 상태를 시작 시킨다.
3. 일정 시간 실행을 시키고 ALTER EVENT SESSION으로 해당 세션을 중지 시킨다.
4. DROP EVENT SESSION으로 해당 이벤트를 삭제한다.

우리는 알고 있다 Microsoft라는 회사가 얼마나 친절한 지를 그래서 TechNet을 찾아본 결과 역시나 예제가 있었다. 예제 : 잠금을 보유한 쿼리 파악 이것이다. 관심 있는 사람들은 직접 TEST를 해보기 바란다.

확장이벤트(XEvent)라는 것에 대해서 이것저것 자료를 찾아보고 있던 중 흥미로운 사실 하나를 알게 되었다. 영어가 잛은 관계로 원문 그대로를 올리겠다.

In my first post on SQL Server 2008, I introduced a new feature called Extended Events (we like to call this Xevent internally). While we were working with the XEvent development team, it dawned on us that we could perhaps build an event session that was "always-on" (in fact internally we were calling this the "Always-On" session). In this session, we could add some events that were perhaps important for troubleshooting certain problems with the SQL Server Engine.
Thus was born the system_health Extended Events session. So if you install SQL Server 2008 RC0, an run the following query:

XEvnet를 개발하던 도중에 XEvent를 "Always-ON" 즉, 항상 실행 상태로 만들어 놓을수 있다는 것을 알게 되었고, 그것을 개발팀에 이야기해 추가를 했다는 내용인것 같다. 그리고 먼가를 실행해 보라는 것이다.

select * from sys.dm_xe_sessions

그렇다. 해당 DMV는 어떤 XEvent session이 실행되고 있는지 보여 주는 것이다. 이 DMV를 실행시키면

위와 같이 system_health라는 세션이 이미 실행되고 있을 것이다. 그리고 해당 세션의 내용을 보려면 다음과 같은 Query을 실행시키라고 나와 있다.

select CAST(xet.target_data as xml) from sys.dm_xe_session_targets xet 
join sys.dm_xe_sessions xe 
on (xe.address = xet.event_session_address) 
where xe.name = 'system_health'

system_health의 내용이 저장되는 곳은(XEvent에서는 target이라고 한다) RingBuffer이며 RingBuffer는 SQL Server가 재시작되면 초기화가 되고 Buffer기반이기 때문에 Buffer가 가득차면 오래된 항목부터 새로운 항목이 덮어써지게 된다고 한다. 그럼 이 System_health는 왜 "Always-ON"을 하고 있는 것일까? 다음과 같은 항목들 때문에 항상 실행되고 있다고 한다. 역시나 영어가 짧기 때문에 원문 그대로를 올린다.

1. The sql_text and session_id for any sessions that encounter an error with severity >= 20
2. The sql_text and session_id for any sessions that encounter a "memory" type of error such as 17803, 701, etc (we added this because not all memory errors are severity >= 20)
3. A record of any "non-yielding" problems (you have sometimes seen these in the ERRORLOG as Msg 17883)
4. Any deadlocks that are detected
5. The callstack, sql_text, and session_id for any sessions who have waited on latches (or other interesting resources) for > 15 seconds
6. The callstack, sql_text, and session_id for any sessions who have waited on locks for > 30 seconds
7. The callstack, sql_text, and session_id for any session that have waited for an extended period of time for "external" waits or "pre-emptive waits".

음. 끄덕끄덕 -0-;; 그럼 위와 같은 문제가 생겼을 때 System_health라는 XEvent에 자동으로 기록이 되는 것일까? 그럼 Blocking에 대해서 TEST를 해보자. 해당 Blocking Query는 "전문가로 가는길3 - SQL Server 2000/2005 튜닝"책에 있는 TEST Query로 하였다.

USE tempdb
GO
DROP TABLE testtable 
GO
CREATE TABLE testtable (a int not null)
INSERT testtable VALUES(1)
GO
 
CREATE PROCEDURE testproc
AS
  PRINT 'testproc 시작'
  UPDATE testtable
    SET a = 12
  PRINT 'testproc 종료'
GO
 
CREATE PROCEDURE exectest
AS
  PRINT 'exectest 시작'
  EXEC testproc
GO

--<세션-1>
DBCC TRACEON(2681, -1)
GO 
BEGIN TRANSACTION
  SELECT * FROM testtable (HOLDLOCK)

--<세션-2>
EXEC exectest

--<세션-1>
ROLLBACK TRAN

위와 같이 인위적으로 Block이 생기게 하고 약 30초 이상 그대로 놔두었다가 ROLLBACK TRAN을 해준다. 그리고 아래 Query를 실행시켜 System_health에 어떻게 기록되었나 살펴보도록 하겠다.

SELECT
	 wait_info.value('(data/value)[1]','nvarchar(max)') as 'wait_type(VALUE)'
	,wait_info.value('(data/text)[1]','nvarchar(max)') as 'wait_type(TEXT)'  
	,wait_info.value('(data/value)[2]','nvarchar(max)') as 'event_opcode(VALUE)'
	,wait_info.value('(data/text)[2]','nvarchar(max)') as 'event_opcode(TEXT)'
	,wait_info.value('(data)[3]','nvarchar(max)') duration
	,wait_info.value('(data)[4]','nvarchar(max)') max_duration
	,wait_info.value('(data)[5]','nvarchar(max)') total_duration
	,wait_info.value('(data)[6]','nvarchar(max)') signal_duration
	,wait_info.value('(data)[7]','nvarchar(max)') completed_count
	,wait_info.value('(action)[1]','nvarchar(max)') callstack
	,wait_info.value('(action)[2]','nvarchar(max)') session_id
	,wait_info.value('(action)[3]','nvarchar(max)') sql_text
FROM (
	SELECT CAST(xest.target_data AS XML) statementdata
	from sys.dm_xe_session_targets xest INNER JOIN sys.dm_xe_sessions xes 
	ON xes.address = xest.event_session_address
	WHERE xest.target_name = 'ring_buffer' AND xes.name = 'system_health'
) statements
CROSS APPLY statementdata.nodes ('//RingBufferTarget/event[@name="wait_info"]') AS a(wait_info)

위 그림과 같이 먼가가 기록이 되어 있다.
참고로 DealLock을 보고 싶으면 //RingBufferTarget/event[@name="wait_info"] 부분을 //RingBufferTarget/event[@name="xml_deadlock_report"] 이렇게 바꾸면 DealLock에 대한 기록이 나온다. 근데 한가지 문제점이 있다. 해당 출력 Query을 봐서 알겠지만, 우리에게 익숙한 Transact-SQL이 아닌듯 하다. 그렇다 XQuery이다. 확장이벤트(XEvent)을 출력하려면 XQuery으로 출력을 해야 한다. 배워야 하는것이다. 배우자 그만한 투자 가치는 있어 보인다.

참고 : http://technet.microsoft.com/ko-kr/library/bb630282.aspx
참고 : http://blogs.msdn.com/psssql/archive/2008/07/15/supporting-sql-server-2008-the-system-health-session.aspx