2006-12-18
데드락 추적하기
SQL 서버에서 데드락이 걸리면 락 매니저는 그 중 하나를 victim 으로 삼아서 죽이게 된다. 문제는 기본 설정 만으로는 어떤 SQL문끼리의 충돌인지를 확인할 수 없다는 점인데, SQL Server 에러 로그를 이용해서 이를 쉽게 알아낼 수 있다.
normal deadlock
dbcc traceon(1204,3605,-1) 를 이용하면, 데드락 이벤트(1204)가 발생할 경우 에러 로그에 남길 수 있다. -1 은 세션 설정이 아닌 서버 전역 설정을 의미한다. 가장 좋은 방법은 시스템 시작 파라미터에다가 -T1204 를 넘겨주는 방식. 단 성능에 문제가 있을 수 있으므로, 데드락을 잡고 나서 끄는 것을 잊지 말도록.
주기적으로 sp_readerrorlog 또는 엔터프라이즈 매니저에서 확인해보다 보면 아래와 같은 로그가 나올 때가 있다.
Deadlock encountered .... Printing deadlock information 0
2006-12-13 14:31:13.11 spid4 0
2006-12-13 14:31:13.11 spid4 Wait-for graph 0
2006-12-13 14:31:13.11 spid4 0
2006-12-13 14:31:13.11 spid4 Node:1 0
2006-12-13 14:31:13.11 spid4 RID: 8:1:3534:228 CleanCnt:1 Mode: X Flags: 0x2 0
2006-12-13 14:31:13.11 spid4 Grant List 2:: 0
2006-12-13 14:31:13.11 spid4 Owner:0x4ae74ca0 Mode: X Flg:0x0 Ref:0 Life:02000000 SPID:64 ECID:0 0
2006-12-13 14:31:13.11 spid4 SPID: 64 ECID: 0 Statement Type: UPDATE Line #: 12 0
2006-12-13 14:31:13.11 spid4 Input Buf: Language Event: insert into take_time_table (type, name, userID, takeTime) values (4, 'PickupServerApp', 50780, 6493) 0
2006-12-13 14:31:13.11 spid4 Requested By: 0
2006-12-13 14:31:13.11 spid4 ResType:LockOwner Stype:'OR' Mode: S SPID:58 ECID:0 Ec:(0x778C9508) Value:0x7321ac20 Cost:(0/1BC) 0
2006-12-13 14:31:13.11 spid4 0
2006-12-13 14:31:13.11 spid4 Node:2 0
2006-12-13 14:31:13.11 spid4 RID: 8:1:3535:117 CleanCnt:1 Mode: X Flags: 0x2 0
2006-12-13 14:31:13.11 spid4 Grant List 1:: 0
2006-12-13 14:31:13.11 spid4 Owner:0x3e54c7c0 Mode: X Flg:0x0 Ref:0 Life:02000000 SPID:58 ECID:0 0
2006-12-13 14:31:13.11 spid4 SPID: 58 ECID: 0 Statement Type: CONDITIONAL Line #: 8 0
2006-12-13 14:31:13.11 spid4 Input Buf: Language Event: insert into take_time_table (type, name, userID, takeTime) values (2, 'GatewayServerApp', 50977, 0) 0
2006-12-13 14:31:13.11 spid4 Requested By: 0
2006-12-13 14:31:13.11 spid4 ResType:LockOwner Stype:'OR' Mode: U SPID:64 ECID:0 Ec:(0x611CD508) Value:0x4ae74e20 Cost:(0/134) 0
2006-12-13 14:31:13.11 spid4 Victim Resource Owner: 0
2006-12-13 14:31:13.11 spid4 ResType:LockOwner Stype:'OR' Mode: U SPID:64 ECID:0 Ec:(0x611CD508) Value:0x4ae74e20 Cost:(0/134) 0
위 로그에 의하면 single insert statement 2개를 동시에 실행할 때 데드락이 걸렸다. 처음에는 legacy 서버에서 스토어드 프로시저 대신 raw SQL을 실행했기 때문에 발생된 것으로 추측했는데, 논리적으로 이 둘이 데드락을 유발시키기는 좀 힘든 상황이었다. 이 경우 dbcc page 명령을 이용하면, 구체적으로 어떤 메모리 페이지에서 락이 걸렸는지를 확인해볼 수 있다. 위 로그에서 RID 부분을 찾아서 넘겨주면 끝. (단 이 명령을 실행하면 역시나 에러 로그에 남기 때문에, 나중에 보고 놀래지 말 것!)
[sql]
dbcc page(8,1,3534,3)
dbcc page(8,1,3535,3)
[/sql]
결국 문제는 저 테이블에는 다른 테이블로 또다시 select & insert 하는 무지몽매한 트리거(-_-)가 걸려 있어서 생긴 문제였다. 하아.
Key deadlock
이번엔 키 데드락 로그를 살펴보자. 이 경우 RID 대신 KEY 라고 나오는데, SELECT OBJECT_NAME(KeyID) 를 이용해서 어떤 오브젝트에서 락이 걸렸는지를 알아낼 수 있다.
Deadlock encountered .... Printing deadlock information 0
2006-12-20 20:37:35.73 spid4 0
2006-12-20 20:37:35.73 spid4 Wait-for graph 0
2006-12-20 20:37:35.73 spid4 0
2006-12-20 20:37:35.73 spid4 Node:1 0
2006-12-20 20:37:35.73 spid4 KEY: 8:612197231:1 (5000dcb808b7) CleanCnt:1 Mode: Range-S-U Flags: 0x0 0
2006-12-20 20:37:35.73 spid4 Grant List 1:: 0
2006-12-20 20:37:35.73 spid4 Grant List 3:: 0
2006-12-20 20:37:35.73 spid4 Owner:0x25bdf860 Mode: Range-S-S Flg:0x0 Ref:0 Life:02000000 SPID:69 ECID:0 0
2006-12-20 20:37:35.73 spid4 SPID: 69 ECID: 0 Statement Type: EXECUTE Line #: 0 0
2006-12-20 20:37:35.73 spid4 Input Buf: RPC Event: sp_cursoropen;1 0
2006-12-20 20:37:35.73 spid4 Requested By: 0
2006-12-20 20:37:35.73 spid4 ResType:LockOwner Stype:'OR' Mode: X SPID:57 ECID:0 Ec:(0x39939508) Value:0x5223ee00 Cost:(0/1070) 0
2006-12-20 20:37:35.73 spid4 0
2006-12-20 20:37:35.73 spid4 Node:2 0
2006-12-20 20:37:35.73 spid4 KEY: 8:612197231:1 (d000bebebbe4) CleanCnt:2 Mode: X Flags: 0x0 0
2006-12-20 20:37:35.73 spid4 Wait List: 0
2006-12-20 20:37:35.73 spid4 Owner:0x3dc49b20 Mode: S Flg:0x0 Ref:1 Life:00000000 SPID:65 ECID:0 0
2006-12-20 20:37:35.73 spid4 SPID: 65 ECID: 0 Statement Type: SELECT Line #: 1 0
2006-12-20 20:37:35.73 spid4 Input Buf: Language Event: select b.charid from user_table a join char_table b on a.userid=b.userid where b.disable=0 and b.usertype=2 and a.username='throwrocks@me.com' 0
2006-12-20 20:37:35.73 spid4 Requested By: 0
2006-12-20 20:37:35.73 spid4 ResType:LockOwner Stype:'OR' Mode: Range-S-S SPID:69 ECID:0 Ec:(0x3A7A1548) Value:0x68dded80 Cost:(0/0) 0
2006-12-20 20:37:35.73 spid4 0
2006-12-20 20:37:35.73 spid4 Node:3 0
2006-12-20 20:37:35.73 spid4 KEY: 8:612197231:1 (d000bebebbe4) CleanCnt:2 Mode: X Flags: 0x0 0
2006-12-20 20:37:35.73 spid4 Grant List 1:: 0
2006-12-20 20:37:35.73 spid4 Owner:0x4f336b40 Mode: X Flg:0x0 Ref:0 Life:02000000 SPID:57 ECID:0 0
2006-12-20 20:37:35.73 spid4 SPID: 57 ECID: 0 Statement Type: UPDATE Line #: 135 0
2006-12-20 20:37:35.73 spid4 Input Buf: RPC Event: U_CharacterSaveLocker;1 0
2006-12-20 20:37:35.73 spid4 Requested By: 0
2006-12-20 20:37:35.73 spid4 ResType:LockOwner Stype:'OR' Mode: S SPID:65 ECID:0 Ec:(0x74FA7548) Value:0x3dc49b20 Cost:(0/0) 0
2006-12-20 20:37:35.73 spid4 Victim Resource Owner: 0
2006-12-20 20:37:35.73 spid4 ResType:LockOwner Stype:'OR' Mode: S SPID:65 ECID:0 Ec:(0x74FA7548) Value:0x3dc49b20 Cost:(0/0) 0
2006-12-20 20:37:40.73 spid4 0
DBCC PSS
DBCC PSS(uid [, spid]) 를 통해서 특정 pid 의 다양한 속성들을 알 수 있다. uid 는 select * from sysusers 로 체크하고, 프로세스는 sp_who2 로 알아내면 된다. 물론 spid 를 생략하면 해당 유저의 모든 프로세스의 정보가 뜬다.
PSS @0x1B9E71E0
---------------
pspid = 53 m_dwLoginFlags = 0x03e0 plsid = 1827921760
pbackground = 0
pbSid
-----
81ee3246 10030a4a 8c19c980 f40a127f ..2F...J........
sSecFlags = 0x2 pdeadlockpri = 0 poffsets = 0x0
pss_stats = 0x0 ptickcount = 905625531
pcputickcount = 2711581261636168 ploginstamp = 313917
ptimestamp = 2006-12-18 03:18:26.550 plangid = 0
pdateformat = 1 pdatefirst = 7 Language = us_english
UserName = ubo_game poptions = 0x28400020 poptions2 = 0x3f438
pline = 1 pcurstepno = 0 prowcount = 1
pstatlist = 0 pcurcmd = 253 pseqstat = 0
ptextsize = 2147483647 pretstat = 0 CNestLevel = 0
@@procid = 0 pslastbatchstarttime = 2006-12-21 23:36:14.363
pmemusage = -2095 hLicense = 0 tpFlags = 0x1
isolation_level = 0 fips_flag = 0x0 sSaveSecFlags = 0x0
psavedb = 0 pfetchstat = 0 pcrsrows = 0
pslastbatchtime = 2006-12-21 23:36:14.363 pubexecdb = 0
fInReplicatedProcExec = 0 pMsqlXact = 0x6D6AD038 presSemCount = [0]0
presSemCount = [0]0 pcputot = 5182694 pcputotstart = 5182694
pcpucmdstart = 5182694 pbufread = 346 pbufreadstart = 346
plogbufread = 11300361 plogbufreadstart = 11300354
pbufwrite = 6374 pbufwritestart = 6374 pLockTimeout = 4294967295
pUtilResultSet = 0x00000000
[sql]
SET SHOWPLAN_ALL ON
SET STATISTICS PROFILE ON
[/sql]
DB에 문제가 생기면 언제나 무료로 컨설팅해주시는 자칭 초보 DBA 창아군에게 Special Thanks를 보낸다.