SQL Server 쿼리 로그로 SQL튜닝이나 프로그램 분석에 사용하기

DBMS 엔진들은 각기 나름의 분석을 위해 수행 과정을 로그로 남길 수 있도록 하는 장치를 두고 있는데, DBMS에 전달된 SQL문의 처리 과정 중에 일부 이벤트를 로그로 남길도록 하여 응답이 너무 느린 쿼리를 찾거나(SQL 튜닝), 응용 프로그램의 DB 사용 패턴을 코드와 무관하게 분석하는데 사용할 수 있습니다. 이번에는 Microsoft SQL Server(MS-SQL)를 기준으로 쿼리 로그를 남기고 조회하는 방법을 살펴보고자 합니다.

예제에서는 마이크로소프트사에서 무료로 다운받을 수 있는 Microsoft SQL Server Express edition과 Microsoft SQL Server Management Studio Express를 사용했습니다.

우선 Microsoft SQL Server Management Studio Express를 실행시키고, 쿼리 로그를 저장할 데이터베이스의 팝업 메뉴에서 New Query를 선택하여 T-SQL를 입력할 수 있는 창을 엽니다.

DECLARE @TraceID INT
DECLARE @ON BIT
DECLARE @RetVal INT
SET @ON = 1
declare @stop datetime
-- 분단위로 5분후에 멈추도록 설정
set @stop = dateadd(mi, 5, getdate())
declare @maxfilesize bigint
-- 최대 크기는 MB단위
set @maxfilesize = 50
-- 파일명뒤에 자동으로 .trc 붙으므로 이름만 지정한다. 동일 파일명이 있으면 실패하므로 확인필
exec @RetVal = sp_trace_create @TraceID OUTPUT, 2, N'D:\ActivityTrace\sqllog', @maxfilesize, @stop 
print 'Trace ID = ' + CAST(@TraceID AS NVARCHAR)
print 'Return value = ' + CAST(@RetVal AS NVARCHAR)
-- 10 = RPC:Completed
exec sp_trace_setevent @TraceID, 10, 1, @ON     -- Textdata
exec sp_trace_setevent @TraceID, 10, 3, @ON     -- DatabaseID
exec sp_trace_setevent @TraceID, 10, 12, @ON    -- SPID
exec sp_trace_setevent @TraceID, 10, 13, @ON    -- Duration
exec sp_trace_setevent @TraceID, 10, 14, @ON    -- StartTime
exec sp_trace_setevent @TraceID, 10, 15, @ON    -- EndTime
-- 41 = SQL:StmtCompleted
exec sp_trace_setevent @TraceID, 41, 1, @ON     -- Textdata
exec sp_trace_setevent @TraceID, 41, 3, @ON     -- DatabaseID
exec sp_trace_setevent @TraceID, 41, 12, @ON    -- SPID
exec sp_trace_setevent @TraceID, 41, 13, @ON    -- Duration
exec sp_trace_setevent @TraceID, 41, 14, @ON    -- StartTime
exec sp_trace_setevent @TraceID, 41, 15, @ON    -- EndTime
-- Trace시작 (status 1 = start, 0=stop, 2=close, 종료시점을 지정한 경우에는 멈추거나 close할 필요없다)
EXEC @RetVal = sp_trace_setstatus @TraceID, 1
GO

그리고 위의 스크립트를 적절하게 수정 및 실행(!Execute)시켜 쿼리 로깅을 시작하면 됩니다. 그런데, 이렇게 로그를 남기도록 설정하면 당연히 DBMS 응답이 느려 질 수 있으므로 사용에 유의해야 합니다. 분석을 위한 작업 시간을 적절하게 예측하여 위의 예제 처럼 적절한 시간 내에 추적 및 로깅이 자동 종료되는 형태로 작업하는 것이 안정적 입니다.

쿼리를 실행시키면 결과창이 위의 그림과 같이 출력되는데 Return value가 0 이어야 추적이 정상적으로 동작하기 시작한것이므로 성공 시점의 Trace ID(매뉴얼로 추적을 중단하거나 닫을때 사용)와 함께 꼭 확인 합니다. 추적을 위한 T-SQL 수행전에 꼭 확인할 부분은 다음과 같습니다.

• 수행시간 : dateadd 부분에 분단위로 입력

• 로그 파일명 : sp_trace_create에 절대 경로로 파일명 입력(확장자 *.trc가 자동으로 붙고, 기존에 동일이름이 있으면 실패하므로 주의)

Trace 중인 상태인지, 어떤 것이 추적중 인지 등의 정보를 확인하려면 아래의 쿼리를 사용하면 됩니다.

-- 현재 설정되어 있는 Trace 정보 조회(종료 시점을 설정한 Trace는 자동 삭제 된다)

SELECT * FROM ::fn_trace_getinfo(default)

정상적으로 쿼리 로깅이 시작되었으면 쿼리를 수행하거나, DB 접근이 필용한 응용을 수행해 봅니다.

앞서 쿼리로깅을 시작할 때 설정한 추적 시간이 지나서 위의 그림과 같이 로그 파일이 생성되면 쿼리로깅이 정상적으로 수행된 것이고 이제는 로깅한 정보를 가지고 분석을 수행 합니다.

로그를 분석하는 것도 로그 파일을 쿼리로 조회할 수 있도록 제공하고 있으므로 DBMS에서 제공하는 기능을 사용하면 됩니다. 로그 조회시 사용하는 SQL은 아래와 같으며 WHERE 문을 통해서 적절하게 필터링 하면 좋은 정보를 추출할 수 있습니다.

-- Trace 설정시 지정한 파일명을 쿼리로 조회할 수 있다.(지정한 필드외에는 NULL이므로 적절하게 필터링해서 보면 된다)

SELECT EventClass, TextData, DatabaseID, SPID, Duration, StartTime, EndTime  

FROM ::fn_trace_gettable('D:\ActivityTrace\sqllog.trc', default)

위의 검색 결과를 보면 Duration 컬럼 값으로 쿼리 단위의 수행 시간을 확인할 수 있는데, 이 값이 일정 수준이상으로 큰 것들만 추출해서 해당 쿼리의 수행 속도를 개선할 수 있도록 SQL 수정, 인덱스 추가, 응용 수정등 여러가지 튜닝 방법을 적용할 수 있습니다.

로깅 파일이 크거나, 기타 속도 등의 이슈로 특정 이벤트만 필터링해서 로깅하고 싶을 때는 아래의 문장과 같이 sp_trace_setfilter 를 적절하게 사용하면 됩니다.

-- 필터링을 사용해서 로그를 정리해서 저장하고 싶을때 Trace시작(sp_trace_setstatus) 전에 기술한다.

-- 수행시간이 10초 초과 인것을 고를때는 수행시간 필드인 13번째 컬럼에 대해서 지정값보다 큰지 확인하는 연산(2)을 지정한다.

declare @duration bigint

set @duration = 10000

exec sp_trace_setfilter @TraceID, 13, 0, 2, @duration