פוסטים אחרונים

תגיות

ניווט

קישורי SQL Server אחרים

הבלוג של פיני קרישר על SQL Azure

ארכיון

חקירת deadlocks ב- SQL Server (חלק 2)

אביאל אילוז

MCT, מומחה ב-SQL Server, בעל 15 שנות ניסיון בתחום ומנהל אקדמי של מכללת נאיה

במאמר הראשון בסדרה זו הכרנו את תופעת ה-deadlock בפירוט והמחשנו אותה באמצעות דוגמא פשוטה. הופעתו של אירוע deadlock דורש את התערבותו של צוות הפיתוח או ה-DBA כדי להתחקות אחר מקורותיו ולעשות את הנדרש כדי למנוע את הישנותו. לשם כך מספק לנו SQL Server כלים שונים לתחקור התופעה. במאמר זה נכיר את אחד מן הכלים האלה ונלמד כיצד לנתח נכון את המידע המופק ממנו אודות מקורותיו של deadlock.

עקוב אחרי!

הכלי הראשון שזורה אור על מקורות אירוע ה-deadlock הוא Trace Flags, 'דגלי מעקב' במינוח העברי, שהם כמו מתגי הפעלה שונים ששולטים על התנהגותו של SQL Server בפרמטרים שונים. ישנם דגלי מעקב רבים מאוד ורובם אינם מתועדים בספרות הרשמית. רשימת דגלי המעקב המותעדים ב-Books On Line איננה ארוכה, אך כוללת את השניים שמעניינים אותנו: 1204 ו-1222. שניהם מאלצים את SQL Server לדבר קצת יותר אל תוך הלוג שלו (Error Log) בעת אירוע deadlock ולתת לנו מידע מפורט על מה שקרה.

ראשית, כדי להפעיל דגל מעקב כל שהוא יש להריץ ע"י פקודת DBCC המקבלת שני פרמטרים:

· מס' הדגל המופעל.

· הטווח (Scope) שלו; (0) עבור החיבור (session) הנוכחי בלבד, (1-) הפעלה גלובלית.

כמו כן, ישנן עוד 2 פקודות חשובות: אחת לביטול הפעלת הדגל והשניה לבדיקת סטטוס ההפעלה שלו. בקטע הקוד הבא מופעל דגל 1222 באופן גלובלי לניטור deadlock, וכן מודגמת פקודת הביטול (TRACEOFF) והבדיקה (TRACESTATUS).

--turn on trace flag 1222 globally

DBCC TRACEON (1222, -1)

--view all trace flags status

DBCC TRACESTATUS

--turn off trace flag 1222 globally

DBCC TRACEOFF (1222, -1)

אם הרצתם את הקוד הנ"ל כולו, הריצו שוב פקודת ההפעלה לדגל 1222 כדי לנטר את אירועי ה-deadlock.

כדי להפעיל דגלי מעקב עם הפעלתו של SQL Server יש לקבוע זאת בפרמטרי האיתחול של SQL Server ולהוסיף את הפרמטר (-T) ואחריו את מספר הדגל. לקריאה כיצד לבצע זאת ראו ב-Startup Options.

בשלב זה, נבחר להפעיל רק דגל 1222 כי המידע שמופק ממנו שלם, מפורט יותר וכולל מידע נוסף הקשור לתהליכים המעורבים באירוע ה-deadlock ועל מצבם. דגל מעקב מספר 1204 מספק מידע פשוט יותר ועל כן גם נוח יותר לניתוח מהיר שלא דורש העמקת יתר. בהמשך המאמר נשווה בקצרה את הפלט שלו לזה של דגל 1222.

בדיקת סטטוס ההפעלה באמצעות TRACESTATUS תראה את הפלט הבא, המעיד שדגל 1222 הופעל באופן גלובלי (הכולל כמובן את רמת ה-session, אף על פי שהיא מסומנת ב-0):

TraceFlag Status Global Session

--------- ------ ------ -------

1222 1 1 0

הפעלת דגל המעקב 1222 מתועדת ב-Error Log של SQL Server בנוסח הבא:

DBCC TRACEON 1222, server process ID (SPID) 51. This is an informational message only; no user action is required.

אנטומיה של אירוע

נחזור כעת לקוד הטרנזקציות שהרצנו במאמר הראשון. נריץ אותו שוב ונראה מהו המידע המופק אל תוך הלוג של SQL Server בעקבות ההפעלה של דגל 1204. כפי שבצענו בפעם הקודמת, נריץ את הקוד של טרנזקציה A בחלון שאילתא אחד ונעבור מייד להריץ את קוד טרנזקציה B בחלון שני:

--Transaction A

USE AdventureWorks2008

BEGIN TRANSACTION

--Statement 1

UPDATE Sales.SalesOrderDetail

SET OrderQty = OrderQty * 2

WHERE SalesOrderID = 43659 and SalesOrderDetailID = 1

--Hold for 10 seconds

WAITFOR DELAY '00:00:10'

--Statement 2

SELECT * FROM HumanResources.Department

WHERE DepartmentID = 1

COMMIT

--Transaction B

USE AdventureWorks2008

BEGIN TRANSACTION

--Statement 1

UPDATE HumanResources.Department

SET Name = Name + ' added text'

WHERE DepartmentID = 1

--Hold for 10 seconds

WAITFOR DELAY '00:00:10'

--Statement 2

SELECT * FROM Sales.SalesOrderDetail

WHERE SalesOrderID = 43659 and SalesOrderDetailID = 1

COMMIT

כמצופה, בחלון השני בוטלה הטרנזקציה והתהליך כולו נבחר כ-victim עם הודעת השגיאה מס' 1205 המודיעה על deadlock.

נבחן כעת את הפלט ב-Error Log בעקבות הפעלת דגל המעקב 1222. את המידע הזה ניתן לראות בשני אופנים:

1. בחלון הצגת רשומות הלוג של SQL Server ב-SSMS כמו בתמונה הבאה (ניתן למיין בסדר תאריך עולה רק בגרסה 2012):

2. בקובץ הלוג האחרון (Current = ERROROG) עצמו הנמצא בספרייתLOG של SQL Server (שם הקובץ ומיקום ברירת המחדל:

C:\Program Files\Microsoft SQL Server\MSSQL10_50.MSSQLSERVER\MSSQL\LOG\ERRORLOG

באפשרות זאת, אפשר לראות את המידע במלואו ולהעתיקו למקום אחר. במקרה שלנו מתקבל הפלט הבא על אירוע ה-deadlock כתוצה מהפעלת דגל המעקב 1222 (בצירוף עריכה קלה והדגשות שונות לצורך תצוגה ברורה):

deadlock-list

deadlock victim=process89bc78

process-list

process id=process89bc78 taskpriority=0 logused=992 waitresource=KEY: 41:72057594059096064 (88d989970b21) waittime=1295 ownerId=1461972 transactionname=user_transaction lasttranstarted=2012-02-01T14:16:17.460 XDES=0x6e68280 lockMode=S schedulerid=1 kpid=9792 status=suspended spid=57 sbid=0 ecid=0 priority=0 trancount=1 lastbatchstarted=2012-02-01T14:16:17.330 lastbatchcompleted=2012-02-01T14:16:17.330 clientapp=Microsoft SQL Server Management Studio - Query hostname=COMP hostpid=8648 loginname=COMP\User isolationlevel=read committed (2) xactid=1461972 currentdb=41 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200

executionStack

frame procname=adhoc line=12 stmtstart=38 sqlhandle=0x0200000062bf1a367c223b2515295d4ab887a612948fe8f8

SELECT * FROM [Sales].[SalesOrderDetail] WHERE [SalesOrderID]=@1 AND [SalesOrderDetailID]=@2

frame procname=adhoc line=12 stmtstart=390 stmtend=578 sqlhandle=0x02000000081dbe017f1c3ce264b5c71a5af5ba8fc624e486

SELECT * FROM Sales.SalesOrderDetail

WHERE SalesOrderID = 43659 and SalesOrderDetailID = 1

inputbuf

BEGIN TRANSACTION

--Statement 1

UPDATE HumanResources.Department

SET Name = Name + ' added text'

WHERE DepartmentID = 1

--Hold for 10 seconds

WAITFOR DELAY '00:00:10'

--Statement 2

SELECT * FROM Sales.SalesOrderDetail

WHERE SalesOrderID = 43659 and SalesOrderDetailID = 1

COMMIT

process id=process5d89558 taskpriority=0 logused=3292 waitresource=KEY: 41:72057594044612608 (e1784bd73cba) waittime=4120 ownerId=1461715 transactionname=user_transaction lasttranstarted=2012-02-01T14:16:14.063 XDES=0x5797b30 lockMode=S schedulerid=2 kpid=6612 status=suspended spid=56 sbid=0 ecid=0 priority=0 trancount=1 lastbatchstarted=2012-02-01T14:16:13.963 lastbatchcompleted=2012-02-01T14:16:13.963 clientapp=Microsoft SQL Server Management Studio - Query hostname=COMP hostpid=8648 loginname=COMP\User isolationlevel=read committed (2) xactid=1461715 currentdb=41 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200

executionStack

frame procname=adhoc line=12 stmtstart=24 sqlhandle=0x02000000f1566f31cd4b8116cb213bf6a38d6f62e123f693

SELECT * FROM [HumanResources].[Department] WHERE [DepartmentID]=@1

frame procname=adhoc line=12 stmtstart=438 stmtend=570 sqlhandle=0x0200000083fb582b676b2b8e21b5289e7168a5a5e6b45d03

SELECT * FROM HumanResources.Department

WHERE DepartmentID = 1

Inputbuf

BEGIN TRANSACTION

--Statement 1

UPDATE Sales.SalesOrderDetail

SET OrderQty = OrderQty * 2

WHERE SalesOrderID = 43659 and SalesOrderDetailID = 1

--Hold for 10 seconds

WAITFOR DELAY '00:00:10'

--Statement 2

SELECT * FROM HumanResources.Department

WHERE DepartmentID = 1

COMMIT

resource-list

keylock hobtid=72057594059096064 dbid=41 objectname=AdventureWorks2008.Sales.SalesOrderDetail indexname=PK_SalesOrderDetail_SalesOrderID_SalesOrderDetailID id=lock55ddf40 mode=X associatedObjectId=72057594059096064

owner-list

owner id=process5d89558 mode=X

waiter-list

waiter id=process89bc78 mode=S requestType=wait

keylock hobtid=72057594044612608 dbid=41 objectname=AdventureWorks2008.HumanResources.Department indexname=PK_Department_DepartmentID id=lockadd2380 mode=X associatedObjectId=72057594044612608

owner-list

owner id=process89bc78 mode=X

waiter-list

waiter id=process5d89558 mode=S requestType=wait

הפלט מציג נתונים מפורטים על התהליכים המעורבים באירוע ה-deadlock באופן הירארכי כמו שמוצג בטבלה הבאה:

אם נבחן את הפלט על פי המבנה הזה נראה אכן שיש לנו שני תהליכים המעורבים באירוע (ואחד מהם הוא victim) ושני משאבים הנעולים על ידם. ננתח זאת כך:

· את המעגליות של הנעילה הגורמת ל-deadlock נוכל לראות בסעיף resource-list המציג את המשאבים הנעולים ביחס לכל אחד משני התהליכים.

· את מספרי התהליכים המופיעים בסעיף זה נשווה למידע המופיע למעלה יותר בסעיף process-list ונוכל לשייך כל אחד מהם לקוד המקורי שלנו.

לשם הבהירות, נמצה מן הפלט כולו רק את המידע העיקרי שיתן לנו את מבוקשנו ונארגן כעת את הנתונים כך שנראה את מצב המשאב הראשון לעומת מצב המשאב השני כפי שעולה מהסעיף resource-list, כמו שמופיע בטבלה הבאה:

מהטבלה נחשפים בבירור מקורותיו של אירוע ה-deadlock כפי שתיארנו אותם בראשית הדברים:

· טרנזקציה A, בתהליך process5d89558, לאחר שביצעה UPDATE בטבלה SalesOrderDetails ועל כן נועלת את המפתח שלה (PK_SalesOrderDetail_SalesOrderID_SalesOrderDetailID) בנעילת X, ממתינה כעת בשאילתת SELECT מהטבלה Department המבקשת נעילת S על המפתח שלה (PK_Department_DepartmentID).

ולעומתה, בדיוק המקרה ההפוך:

· טרנזקציה B, בתהליך process89bc78, לאחר שביצעה UPDATE בטבלה Department ועל כן נועלת את המפתח שלה (PK_Department_DepartmentID) בנעילת X, ממתינה כעת בשאילתת SELECT מהטבלה SalesOrderDetails המבקשת נעילת S על המפתח שלה (PK_SalesOrderDetail_SalesOrderID_SalesOrderDetailID).

כלומר, כל אחד מהתהליכים נועל משאב מסוים המבוקש ע"י התהליך האחר, והוא עצמו ממתין למשאב התפוס כבר ע"י התהליך האחר, וכך שני התהליכים ממתינים זה לזה ומופיע deadlock.

לאחר שהפקנו את המידע, ניתחנו אותו ולמדנו כיצד הופיע אירוע ה-deadlock נוכל כעת לגשת לקוד המקורי באפליקציה ולטפל בו על מנת למונע השנות האירוע בעתיד. במקרה הספציפי הזה, יש לגשת לשתי הטבלאות בדר קבוע בשתי הטרנזקציות וכך למנוע deadlock. במקרים אחרים ובמיוחד כאלה שלא נובעים משגיאות פיתוח קוד, נדרשת פעולות אחרות לגמרי.

סיכום

במאמר הזה ראינו כיצד לנטר מידע על אירועי deadlock באמצעות דגל המעקב (trace flag) מספר 1222. המידע המופק מדגל המעקב מספר 1204 איננו שונה באופן עקרוני, אך הוא פחות מפורט, וישDBA המעדיפים להשתמש בו. בכל אופן, ניתוח המידע וההתחקות אחר מקורות ה-deadlock איננו פשוט כל כך, אך הכרת מבנה פלט המידע על האירוע וניתוח מסודר ומובנה שלו יחשוף בפנינו בסופו של דבר את גורמי התופעה.