Estamos vendo impasses intermitentes na produção ao receber várias solicitações de API simultâneas. Cada requisição basicamente culmina em uma instrução INSERT na mesma tabela, que é onde vemos o impasse. Escrevi um aplicativo de console de thread duplo que pode reproduzir o problema de maneira confiável simplesmente executando duas solicitações de API simultaneamente, mas apenas na produção, não na preparação. (Isso me leva a acreditar que há algo sobre nosso banco de dados de teste - possivelmente o volume de dados, SQL Server 2012 vs 2005 ou ajuste de índice - que difere da produção de forma que o impasse é evitado. O código é idêntico, como acredito ser o esquema.)
Como agora posso reproduzir o impasse, consegui convencer meu chefe a ativar o sinalizador de rastreamento 1222 temporariamente e capturei o log abaixo:
Date,Source,Severity,Message
09/05/2013 16:32:19,spid71,Unknown,DBCC TRACEOFF 1222<c/> server process ID (SPID) 71. This is an informational message only; no user action is required.
09/05/2013 16:30:55,spid17s,Unknown,waiter id=processf34868 mode=X requestType=wait
09/05/2013 16:30:55,spid17s,Unknown,waiter-list
09/05/2013 16:30:55,spid17s,Unknown,owner id=processf35c18 mode=X
09/05/2013 16:30:55,spid17s,Unknown,owner-list
09/05/2013 16:30:55,spid17s,Unknown,objectlock lockPartition=0 objid=428945000 subresource=FULL dbid=8 objectname=MyDB.DomainTransferRAR id=lock120a72c80 mode=X associatedObjectId=428945000
09/05/2013 16:30:55,spid17s,Unknown,waiter id=processf35c18 mode=X requestType=convert
09/05/2013 16:30:55,spid17s,Unknown,waiter-list
09/05/2013 16:30:55,spid17s,Unknown,owner id=processf34868 mode=IX
09/05/2013 16:30:55,spid17s,Unknown,owner-list
09/05/2013 16:30:55,spid17s,Unknown,objectlock lockPartition=0 objid=2096426938 subresource=FULL dbid=8 objectname=MyDB.DomainTransferRANT id=lock11de95480 mode=IX associatedObjectId=2096426938
09/05/2013 16:30:55,spid17s,Unknown,resource-list
09/05/2013 16:30:55,spid17s,Unknown,VALUES (@p0<c/>
09/05/2013 16:30:55,spid17s,Unknown,(@p0 uniqueidentifier<c/>@p1 int<c/>@p2 int<c/>@p3 varchar(8000)<c/>@p4 char(5)<c/>@p5 int<c/>@p6 datetime<c/>@p7 datetime<c/>@p8 varchar(8000)<c/>@p9 char(5)<c/>@p10 int<c/>@p11 datetime<c/>@p12 datetime<c/>@p13 varchar(8000)<c/>@p14 int<c/>@p15 xml<c/>@p16 datetime<c/>@p17 datetime<c/>@p18 varchar(8000)<c/>@p19 datetime<c/>@p20 datetime<c/>@p21 varchar(8000)<c/>@p22 bit<c/>@p23 varchar(8000)<c/>@p24 varchar(8000)<c/>@p25 uniqueidentifier)INSERT INTO [dbo].[DomainTransferRANT]([DomainTransferRANTGUID]<c/> [PrebookedBillPackageId]<c/> [domainID]<c/> [DomainName]<c/> [GainingWNAccountID]<c/> [GainingRegistrantID]<c/> [dtGainingRequestSent]<c/> [dtGainingResponseReceived]<c/> [DomainTransferGainingPartyRespCode]<c/> [LosingWNAccountID]<c/> [LosingRegistrantID]<c/> [dtLosingRequestSent]<c/> [dtLosingResponseReceived]<c/> [DomainTransferLosingPartyRespCode]<c/> [SubmittedBillPackageId]<c/> [ExtraInfo]<c/> [dtRequestSentToRegistry]<c/> [dtResponseFromRegistry]<c/> [DomainTransferRegistryRespCode]<c/> [dtDeleted]<c/> [dtLastChecked]<c/> [DomainTransferStatusCode]<c/> [SendConfirmationForEachDomain]<c/> [SummaryStatus]<c/> [WHOISBeforeTransfer])
09/05/2013 16:30:55,spid17s,Unknown,inputbuf
09/05/2013 16:30:55,spid17s,Unknown,unknown
09/05/2013 16:30:55,spid17s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
09/05/2013 16:30:55,spid17s,Unknown,VALUES (@p0<c/> @p1<c/> @p2<c/> @p3<c/> @p4<c/> @p5<c/> @p6<c/> @p7<c/> @p8<c/> @p9<c/> @p10<c/> @p11<c/> @p12<c/> @p13<c/> @p14<c/> @p15<c/> @p16<c/> @p17<c/> @p18<c/> @p19<c/> @p20<c/> @p21<c/> @p22<c/> @p23<c/> @p24)
09/05/2013 16:30:55,spid17s,Unknown,INSERT INTO [dbo].[DomainTransferRANT]([DomainTransferRANTGUID]<c/> [PrebookedBillPackageId]<c/> [domainID]<c/> [DomainName]<c/> [GainingWNAccountID]<c/> [GainingRegistrantID]<c/> [dtGainingRequestSent]<c/> [dtGainingResponseReceived]<c/> [DomainTransferGainingPartyRespCode]<c/> [LosingWNAccountID]<c/> [LosingRegistrantID]<c/> [dtLosingRequestSent]<c/> [dtLosingResponseReceived]<c/> [DomainTransferLosingPartyRespCode]<c/> [SubmittedBillPackageId]<c/> [ExtraInfo]<c/> [dtRequestSentToRegistry]<c/> [dtResponseFromRegistry]<c/> [DomainTransferRegistryRespCode]<c/> [dtDeleted]<c/> [dtLastChecked]<c/> [DomainTransferStatusCode]<c/> [SendConfirmationForEachDomain]<c/> [SummaryStatus]<c/> [WHOISBeforeTransfer])
09/05/2013 16:30:55,spid17s,Unknown,frame procname=adhoc line=1 stmtstart=738 stmtend=2322 sqlhandle=0x0200000038d7940c60b76abf51c3cf1bc774fe27ba136260
09/05/2013 16:30:55,spid17s,Unknown,select @iLockDummy = 1 from DomainTransferRANT with (TABLOCKX<c/> HOLDLOCK) OPTION(EXPAND VIEWS)
09/05/2013 16:30:55,spid17s,Unknown,frame procname=MyDB.tri_DomainTransferRANT_InsUpd line=68 stmtstart=10336 stmtend=10544 sqlhandle=0x03000800c8c31e75b259fa002fa200000000000000000000
09/05/2013 16:30:55,spid17s,Unknown,executionStack
09/05/2013 16:30:55,spid17s,Unknown,process id=processf35c18 taskpriority=0 logused=2992 waitresource=OBJECT: 8:2096426938:0 waittime=171 ownerId=26880196297 transactionname=user_transaction lasttranstarted=2013-09-05T16:30:55.710 XDES=0x1c7b18b60 lockMode=X schedulerid=2 kpid=34404 status=suspended spid=69 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2013-09-05T16:30:55.763 lastbatchcompleted=2013-09-05T16:30:55.710 clientapp=.Net SqlClient Data Provider hostname=WEB1 hostpid=13216 loginname=client isolationlevel=serializable (4) xactid=26880196297 currentdb=8 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128056
09/05/2013 16:30:55,spid17s,Unknown,VALUES (@p0<c/>
09/05/2013 16:30:55,spid17s,Unknown,(@p0 uniqueidentifier<c/>@p1 int<c/>@p2 int<c/>@p3 varchar(8000)<c/>@p4 char(5)<c/>@p5 int<c/>@p6 datetime<c/>@p7 datetime<c/>@p8 varchar(8000)<c/>@p9 char(5)<c/>@p10 int<c/>@p11 datetime<c/>@p12 datetime<c/>@p13 varchar(8000)<c/>@p14 int<c/>@p15 xml<c/>@p16 datetime<c/>@p17 datetime<c/>@p18 varchar(8000)<c/>@p19 datetime<c/>@p20 datetime<c/>@p21 varchar(8000)<c/>@p22 bit<c/>@p23 varchar(8000)<c/>@p24 varchar(8000)<c/>@p25 uniqueidentifier)INSERT INTO [dbo].[DomainTransferRANT]([DomainTransferRANTGUID]<c/> [PrebookedBillPackageId]<c/> [domainID]<c/> [DomainName]<c/> [GainingWNAccountID]<c/> [GainingRegistrantID]<c/> [dtGainingRequestSent]<c/> [dtGainingResponseReceived]<c/> [DomainTransferGainingPartyRespCode]<c/> [LosingWNAccountID]<c/> [LosingRegistrantID]<c/> [dtLosingRequestSent]<c/> [dtLosingResponseReceived]<c/> [DomainTransferLosingPartyRespCode]<c/> [SubmittedBillPackageId]<c/> [ExtraInfo]<c/> [dtRequestSentToRegistry]<c/> [dtResponseFromRegistry]<c/> [DomainTransferRegistryRespCode]<c/> [dtDeleted]<c/> [dtLastChecked]<c/> [DomainTransferStatusCode]<c/> [SendConfirmationForEachDomain]<c/> [SummaryStatus]<c/> [WHOISBeforeTransfer])
09/05/2013 16:30:55,spid17s,Unknown,inputbuf
09/05/2013 16:30:55,spid17s,Unknown,unknown
09/05/2013 16:30:55,spid17s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
09/05/2013 16:30:55,spid17s,Unknown,VALUES (@p0<c/> @p1<c/> @p2<c/> @p3<c/> @p4<c/> @p5<c/> @p6<c/> @p7<c/> @p8<c/> @p9<c/> @p10<c/> @p11<c/> @p12<c/> @p13<c/> @p14<c/> @p15<c/> @p16<c/> @p17<c/> @p18<c/> @p19<c/> @p20<c/> @p21<c/> @p22<c/> @p23<c/> @p24)
09/05/2013 16:30:55,spid17s,Unknown,INSERT INTO [dbo].[DomainTransferRANT]([DomainTransferRANTGUID]<c/> [PrebookedBillPackageId]<c/> [domainID]<c/> [DomainName]<c/> [GainingWNAccountID]<c/> [GainingRegistrantID]<c/> [dtGainingRequestSent]<c/> [dtGainingResponseReceived]<c/> [DomainTransferGainingPartyRespCode]<c/> [LosingWNAccountID]<c/> [LosingRegistrantID]<c/> [dtLosingRequestSent]<c/> [dtLosingResponseReceived]<c/> [DomainTransferLosingPartyRespCode]<c/> [SubmittedBillPackageId]<c/> [ExtraInfo]<c/> [dtRequestSentToRegistry]<c/> [dtResponseFromRegistry]<c/> [DomainTransferRegistryRespCode]<c/> [dtDeleted]<c/> [dtLastChecked]<c/> [DomainTransferStatusCode]<c/> [SendConfirmationForEachDomain]<c/> [SummaryStatus]<c/> [WHOISBeforeTransfer])
09/05/2013 16:30:55,spid17s,Unknown,frame procname=adhoc line=1 stmtstart=738 stmtend=2322 sqlhandle=0x0200000038d7940c60b76abf51c3cf1bc774fe27ba136260
09/05/2013 16:30:55,spid17s,Unknown,select @iLockDummy = 1 from DomainTransferRAR with (TABLOCKX<c/> HOLDLOCK) OPTION(EXPAND VIEWS)
09/05/2013 16:30:55,spid17s,Unknown,frame procname=MyDB.tri_DomainTransferRANT_InsUpd line=67 stmtstart=10140 stmtend=10334 sqlhandle=0x03000800c8c31e75b259fa002fa200000000000000000000
09/05/2013 16:30:55,spid17s,Unknown,executionStack
09/05/2013 16:30:55,spid17s,Unknown,process id=processf34868 taskpriority=0 logused=3000 waitresource=OBJECT: 8:428945000:0 waittime=171 ownerId=26880196295 transactionname=user_transaction lasttranstarted=2013-09-05T16:30:55.710 XDES=0x1c7b18370 lockMode=X schedulerid=2 kpid=13932 status=suspended spid=93 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2013-09-05T16:30:55.770 lastbatchcompleted=2013-09-05T16:30:55.710 clientapp=.Net SqlClient Data Provider hostname=MYDB hostpid=13216 loginname=client isolationlevel=serializable (4) xactid=26880196295 currentdb=8 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128056
09/05/2013 16:30:55,spid17s,Unknown,process-list
09/05/2013 16:30:55,spid17s,Unknown,deadlock victim=processf35c18
09/05/2013 16:30:55,spid17s,Unknown,deadlock-list
09/05/2013 16:30:08,spid71,Unknown,DBCC TRACEON 1222<c/> server process ID (SPID) 71. This is an informational message only; no user action is required.
Uma coisa a observar é que há um gatilho na inserção na tabela relevante. O gatilho é necessário para determinar um código de status para o registro geral, que pode depender de registros irmãos na mesma tabela. Por muito tempo pensamos que o gatilho era a causa dos impasses, então adicionamos dicas de bloqueio cada vez mais agressivas ao gatilho, culminando na configuração atual onde fazemos um TABLOCKX, HOLDLOCK na(s) tabela(s) relevante(s) antes da seção crítica. Achamos que isso evitaria completamente os impasses, às custas de algum desempenho, serializando efetivamente todas as inserções. Mas parece que não é o caso. Pelo que entendi, algo mais anterior aos nossos bloqueios de tabela exclusivos já deve estar mantendo um bloqueio compartilhado ou atualizado. Mas o que?
Outras informações que podem te ajudar a me ajudar: A tabela DomainTransferRANT é altamente indexada. Sua chave primária é um GUID não agrupado. Há um índice clusterizado em outra coluna INT importante. E há outros 7 índices não agrupados. Finalmente, existem várias restrições de chave estrangeira.
Não tive a chance de executar novamente o rastreamento e capturar o arquivo XDL mais bem formatado, mas, enquanto isso, consegui resolver o problema removendo todo o nível de isolamento e dicas de bloqueio do gatilho e modificando o código do aplicativo para executar o próprio INSERT de dentro de uma transação serializável .
O aplicativo usa LINQ to SQL, portanto, a instrução INSERT é gerada dinamicamente e executada no nível de isolamento READ COMMITTED padrão. A partir do rastreamento de deadlock, pude perceber que os bloqueios obtidos pelo INSERT estavam em conflito com os bloqueios obtidos pelo gatilho. O impasse estava acontecendo mesmo depois de remover todas as dicas de isolamento e bloqueio do gatilho, então presumi que as instruções UPDATE do gatilho estavam causando bloqueios mais fortes do que a instrução INSERT. E quando a transação simultânea concorrente tentou fazer a mesma coisa, ocorreu o impasse.
Definitivamente, estávamos no caminho certo com nossas tentativas de soluções anteriores: usando níveis de isolamento mais altos e travamento mais forte no gatilho. O problema é que os bloqueios mais fracos já foram obtidos pela instrução INSERT gerada pelo LINQ to SQL, antes mesmo de o gatilho ser chamado. A solução é iniciar explicitamente uma transação em nosso código .NET usando o nível de isolamento SERALIZABLE, fazer o insert nessa transação, deixar o gatilho acontecer na mesma transação (sem alterar o nível de isolamento ou dicas de bloqueio) e depois confirmar e descartar a transação . Quando fiz isso, não consegui mais reproduzir o problema (até coloquei de volta no modo antigo e verifiquei que o problema voltou). Aqui está o novo código:
Normalmente, evitamos abrir transações de dentro do código do lado do cliente, porque elas podem ser executadas por muito tempo se o código fizer chamadas de API remotas, causando bloqueio excessivo. Mas, neste caso, estamos isolando um pedaço muito pequeno de código e temos um tratamento robusto de erro/reversão em torno dele.
Uma solução alternativa seria implementar procedimentos armazenados que fazem INSERTs dentro de transações SERIALIZABLE explícitas e, em seguida, alterar o DataContext para chamar o procedimento armazenado . No entanto, essa solução é menos sustentável, pois requer a atualização do procedimento armazenado e da definição de DataContext sempre que o esquema é alterado.
Finalmente, outra possível solução alternativa seria examinar o log de impasse em detalhes e encontrar uma maneira de ajustar nossos índices ou chaves para evitar o impasse em primeiro lugar. No entanto, isso é mais difícil e pode não ser possível com o nosso design.
Acho que a solução acima é a mais simples e compreensível para futuros desenvolvedores.