Soci (Soczó Zsolt) szakmai blogja

2012.07.20.

Megoldás a deadlockos cikkhez

Heuréka! :)

Előzmény.

Az előzményben látható első deadlock lenyomata xmlben így néz ki:

<deadlock-list>
	<deadlock victim="process3c3dc8">
		<process-list>
			<process id="process3c3dc8"
					 taskpriority="0"
					 logused="236"
					 waitresource="KEY: 6:72057594959101952 (8194443284a0)"
					 waittime="8196"
					 ownerId="724347"
					 transactionname="user_transaction"
					 lasttranstarted="2012-07-17T13:30:06.643"
					 XDES="0x9dec3b0"
					 lockMode="U"
					 schedulerid="3"
					 kpid="2744"
					 status="suspended"
					 spid="85"
					 sbid="0"
					 ecid="0"
					 priority="0"
					 trancount="1"
					 lastbatchstarted="2012-07-17T13:30:06.643"
					 lastbatchcompleted="2012-07-17T13:30:06.643"
					 clientapp=".Net SqlClient Data Provider"
					 hostname="AlmaDEVWEB02"
					 hostpid="1312"
					 loginname="BuildAgentUser"
					 isolationlevel="repeatable read (3)"
					 xactid="724347"
					 currentdb="6"
					 lockTimeout="4294967295"
					 clientoption1="673316896"
					 clientoption2="128056">
				<executionStack>
					<frame procname="AlmaDev.dbo.spExecuteTransaction"
						   line="136"
						   stmtstart="7378"
						   stmtend="7554"
						   sqlhandle="0x0300060069e52875f254de0091a000000100000000000000">
						SELECT @toBalance = Balance FROM Account WITH (UPDLOCK) WHERE Id = @toAccountID
					</frame>
				</executionStack>
				<inputbuf>
					Proc [Database Id = 6 Object Id = 1965614441]
				</inputbuf>
			</process>
			<process id="processbe41288"
					 taskpriority="0"
					 logused="236"
					 waitresource="KEY: 6:72057594959101952 (8194443284a0)"
					 waittime="2505"
					 ownerId="724314"
					 transactionname="user_transaction"
					 lasttranstarted="2012-07-17T13:30:06.610"
					 XDES="0x9af4e80"
					 lockMode="X"
					 schedulerid="2"
					 kpid="4716"
					 status="suspended"
					 spid="108"
					 sbid="0"
					 ecid="0"
					 priority="0"
					 trancount="2"
					 lastbatchstarted="2012-07-17T13:30:06.610"
					 lastbatchcompleted="2012-07-17T13:30:06.610"
					 clientapp=".Net SqlClient Data Provider"
					 hostname="AlmaDEVWEB02"
					 hostpid="1312"
					 loginname="BuildAgentUser"
					 isolationlevel="repeatable read (3)"
					 xactid="724314"
					 currentdb="6"
					 lockTimeout="4294967295"
					 clientoption1="673316896"
					 clientoption2="128056">
				<executionStack>
					<frame procname="AlmaDev.dbo.spExecuteTransaction"
						   line="138"
						   stmtstart="7556"
						   stmtend="7830"
						   sqlhandle="0x0300060069e52875f254de0091a000000100000000000000">
						UPDATE Account SET
						Balance += (@amount - @commissionAmount)
						WHERE Id = @toAccountID
					</frame>
				</executionStack>
				<inputbuf>
					Proc [Database Id = 6 Object Id = 1965614441]
				</inputbuf>
			</process>
		</process-list>
		<resource-list>
			<keylock hobtid="72057594959101952"
					 dbid="6"
					 objectname="AlmaDev.dbo.Account"
					 indexname="PK_Account"
					 id="lockc99fc00"
					 mode="U"
					 associatedObjectId="72057594959101952">
				<owner-list>
					<owner id="processbe41288"
						   mode="U"/>
				</owner-list>
				<waiter-list>
					<waiter id="process3c3dc8"
							mode="U"
							requestType="convert"/>
				</waiter-list>
			</keylock>
			<keylock hobtid="72057594959101952"
					 dbid="6"
					 objectname="AlmaDev.dbo.Account"
					 indexname="PK_Account"
					 id="lockc99fc00"
					 mode="U"
					 associatedObjectId="72057594959101952">
				<owner-list>
					<owner id="process3c3dc8"
						   mode="S"/>
				</owner-list>
				<waiter-list>
					<waiter id="processbe41288"
							mode="X"
							requestType="convert"/>
				</waiter-list>
			</keylock>
		</resource-list>
	</deadlock>
</deadlock-list>

Figyeljük meg, hogy mindkét processz a “KEY: 6:72057594959101952 (8194443284a0)” kulcson várakozik, ezen vesztek össze.

Viszont az xmlben nem az van, mint a képen!!!

Az xml vége felé látszik ki-mit ownol. owner-list/owner elemek:

		<resource-list>
				<owner-list>
					<owner id="processbe41288" mode="U"/>
				</owner-list>
				<waiter-list>
					<waiter id="process3c3dc8" mode="U" requestType="convert"/>
				</waiter-list>
			</keylock>
				<owner-list>
					<owner id="process3c3dc8" mode="S"/> <!-- Ez nem U !!! -->
				</owner-list>
				<waiter-list>
					<waiter id="processbe41288" mode="X" requestType="convert"/>
				</waiter-list>
			</keylock>
		</resource-list>

A második processz nem U lockot tart az erőforráson, hanem S-t, Shared lockot! De miért U látszik a képen? A bugos kutya életbe!
Így már kristálytiszta a dolog. Azt nem értettem, hogy tudott kiadni az SQL Server két U lockot ugyanarra az erőforrásra. Sehogy, az elmélet jó. Csak az SSMS bugos.

Tehet, mit látunk itt tképpen? Az egyik processz tart U lockot a közös erőforrásra (owner id=”processbe41288″ mode=”U”), a másik pedig egy Shared lockot (owner id=”process3c3dc8″ mode=”S”). Miért shared az egyik? Mivel valamelyik korábbi sorban (ez nem látszik az xmlből, már lefutott) lemaradt a with(updlock) a select utáni tábla mögül.
Ez az alapállás. Aztán az egyik Update lockra akar konvertálni (waiter id=”process3c3dc8″ mode=”U” requestType=”convert”, ez nem teljesen világos miért, mivel eleve az van neki. A másik Sharedről eXclusive-ra akar konvertálni. Ez már a nem megy, mivel az X nem kompatibilis az U-val, így az nem adható ki, a második processznek várnia kell, de mivel az első által kért U sem a U-val, így összeakadnak.
Míg most sem teljesen tiszta minden, az XML-ben sem látni az összes részletet, pl. miért van az U-U konverzió, de a megoldás viszonylag 100%-ra a következő: át kell nézni a beteg tárolt eljárást, és meg kell keresni benne olyan select-et, amely az Account táblát nem updlockkal érik el. Ezekre fel kell rakni az updlockot, és valószínűleg kiesik a deadlock.
Tanulság: nem elég a deadlock graph grafikus nézetét megnézni, bele kell kukkantani az xml-be is, ha valami nem logikus.
Ezt tudva már más is találkozott ezzel: http://rusanu.com/2010/05/12/the-puzzle-of-u-locks-in-deadlock-graphs/
Szóval még nem teljesen tiszta minden, de az IT már csak ilyen, félinformációk alapján is tudni kell hibát keresni.

4 Comments

  1. Múltkor futottam bele olyanba, hogy egy SELECT nolock hinttel lockolt egy másik folyamatot :-)

    Comment by Zsolt — 2012.10.03. @ 18:31

  2. Na, ezt hogy csinálta?

    Comment by Soczó Zsolt — 2012.10.11. @ 09:21

  3. Hát úgy, hogy mégse a nolock okozta a problémát, csak még lenne mit javítani a lockok trace-lésén.

    Két dolog volt a gyanús.
    1.) Két olyan tábla akadt össze, ami egymástól független.
    2.) Nolock hint lockol.

    Aztán kis törpengéssel rájöttem, hogy olyan műveletet kell keressek a trace-ekben, ahol a két tábla 1 tranzakcióban van.

    Meg is lett, demózom:

    SESSION 1 első batch:
    BEGIN TRAN

    SESSION 1 második batch:
    UPDATE egyiktábla SET valami …

    SESSION 1 harmadik batch:
    SELECT … FROM másiktábla (NOLOCK) …

    SESSION 2:
    SELECT count(*) FROM egyiktábla

    SESSION 1 még nincs egy ideig negyik batch.

    És a lock trace nem az egész tranzakciót tette bele, csak a NOLOCK-os batch-et, azaz a legutolsó batch-et a tranzakcióból, mint lockoló folyamat.

    Comment by Zsolt — 2012.10.21. @ 08:36

  4. Óh, ez a szopás ismerős. Látsz valamit, de nem is az volt a gond okozója. Köszi az infót.

    Comment by Soczó Zsolt — 2012.10.22. @ 20:52

RSS feed for comments on this post.

Sorry, the comment form is closed at this time.

Powered by WordPress