EPiServer DataFactory deadlock exception

Recently we faced a problem in one of our websites where some pages would randomly fail to load and a deadlock exception would be thrown from EPiServer.DataAccess.DatabaseFactory: “Failing because of deadlock.”

At this point we suspected that some other process might be locking some rows out thus causing the loading of our page to fail.

Drilling down the logs, we found out a bit more of what was causing the pages to fail:

<event logger="EPiServer.DataAccess.DatabaseFactory" timestamp="2010-09-23T14:08:29.359375+01:00" level="ERROR" thread="13" domain="/LM/W3SVC/1" username="NT AUTHORITY\NETWORK SERVICE">
  <message>Failing because of deadlock.</message>
  <properties>
    <data name="log4net:HostName" value="web1" />
  </properties>
  <exception>
    <![CDATA[System.Data.SqlClient.SqlException: Transaction (Process ID 137) was deadlocked on lock | communication buffer resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
  </exception>
</event>

Our initial suspicions were correct, we were facing an issue were another process was locking the rows that we needed in order to load the page.

Continuing our investigation, we turned on SQL lock tracing and watched the error logs while we refreshed the page.

DBCC TRACEON (1222, -1)
 
09/23/2010 09:08:00,spid14s,Unknown,deadlock-list
09/23/2010 09:08:00,spid14s,Unknown,deadlock victim=process3812c208                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,process-list                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,process id=processc6ab68 taskpriority=0 logused=20000 waittime=187 schedulerid=5 kpid=11600 status=suspended spid=98 sbid=0 ecid=0 priority=0 transcount=0 lastbatchstarted=2010-09-23T09:08:00.123 lastbatchcompleted=2010-09-23T09:08:00.123 clientapp=.Net SqlClient Data Provider hostname=WEB2 hostpid=4548 loginname=sa isolationlevel=read committed (2) xactid=72110112461 currentdb=17 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
09/23/2010 09:08:00,spid14s,Unknown,executionStack
09/23/2010 09:08:00,spid14s,Unknown,frame procname=dbEPiServer.dbo.netPropertySearchString line=21 stmtstart=1064 stmtend=3640 sqlhandle=0x030011009d4ce3523d5771005d9d00000100000000000000
09/23/2010 09:08:00,spid14s,Unknown,SELECT DISTINCT(tblProperty.fkPageID)<nl/>    FROM       tblProperty<nl/>    INNER JOIN tblPageDefinition ON tblPageDefinition.pkID=tblProperty.fkPageDefinitionID<nl/>    INNER JOIN tblTree ON tblTree.fkChildID=tblProperty.fkPageID<nl/>    INNER JOIN tblPageLanguage ON tblPageLanguage.fkPageID=tblProperty.fkPageID<nl/>    WHERE <nl/>             [email protected] <nl/>    AND [email protected]<nl/>    AND (@LangBranchID=-1 OR [email protected] OR tblPageDefinition.LanguageSpecific=0)<nl/>    AND<nl/>    (<nl/>        (    /*STRING*/<nl/>
09/23/2010 09:08:00,spid14s,Unknown,inputbuf
09/23/2010 09:08:00,spid14s,Unknown,Proc [Database Id = 17 Object Id = 1390627997]                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,process id=processdac5c8 taskpriority=0 logused=4560 waitresource=OBJECT: 17:1349579846:0  waittime=1906 ownerId=72110076172 transactionname=user_transaction lasttranstarted=2010-09-23T09:07:58.390 XDES=0x302d0250 lockMode=IX schedulerid=8 kpid=8432 status=suspended spid=51 sbid=0 ecid=0 priority=0 transcount=3 lastbatchstarted=2010-09-23T09:07:58.390 lastbatchcompleted=2010-09-23T09:07:58.390 clientapp=.Net SqlClient Data Provider hostname=WEB1 hostpid=3780 loginname=sa isolationlevel=read committed (2) xactid=72110076172 currentdb=17 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128056
09/23/2010 09:08:00,spid14s,Unknown,executionStack
09/23/2010 09:08:00,spid14s,Unknown,frame procname=dbEPiServer.dbo.editPublishPageVersion line=97 stmtstart=6296 stmtend=6818 sqlhandle=0x03001100cb6e6d758593cc004b9b00000100000000000000
09/23/2010 09:08:00,spid14s,Unknown,DELETE FROM <nl/>        tblProperty<nl/>    FROM <nl/>        tblProperty<nl/>    INNER JOIN<nl/>        tblPageDefinition ON fkPageDefinitionID=pkID<nl/>    WHERE <nl/>        [email protected] AND<nl/>        fkPageTypeID IS NOT NULL AND<nl/>
09/23/2010 09:08:00,spid14s,Unknown,inputbuf
09/23/2010 09:08:00,spid14s,Unknown,Proc [Database Id = 17 Object Id = 1970106059]                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,process id=process9068e38 taskpriority=0 logused=20026 waittime=93 schedulerid=1 kpid=8036 status=suspended spid=98 sbid=0 ecid=2 priority=0 transcount=0 lastbatchstarted=2010-09-23T09:08:00.123 lastbatchcompleted=2010-09-23T09:08:00.123 clientapp=.Net SqlClient Data Provider hostname=WEB2 hostpid=4548 isolationlevel=read committed (2) xactid=72110112461 currentdb=17 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
09/23/2010 09:08:00,spid14s,Unknown,executionStack
09/23/2010 09:08:00,spid14s,Unknown,frame procname=dbEPiServer.dbo.netPropertySearchString line=21 stmtstart=1064 stmtend=3640 sqlhandle=0x030011009d4ce3523d5771005d9d00000100000000000000
09/23/2010 09:08:00,spid14s,Unknown,SELECT DISTINCT(tblProperty.fkPageID)<nl/>    FROM       tblProperty<nl/>    INNER JOIN tblPageDefinition ON tblPageDefinition.pkID=tblProperty.fkPageDefinitionID<nl/>    INNER JOIN tblTree ON tblTree.fkChildID=tblProperty.fkPageID<nl/>    INNER JOIN tblPageLanguage ON tblPageLanguage.fkPageID=tblProperty.fkPageID<nl/>    WHERE <nl/>             [email protected] <nl/>    AND [email protected]<nl/>    AND (@LangBranchID=-1 OR [email protected] OR tblPageDefinition.LanguageSpecific=0)<nl/>    AND<nl/>    (<nl/>        (    /*STRING*/<nl/>
09/23/2010 09:08:00,spid14s,Unknown,inputbuf                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,process id=process3812c208 taskpriority=0 logused=0 waitresource=PAGE: 17:1:726012 waittime=78 ownerId=72110112461 transactionname=SELECT lasttranstarted=2010-09-23T09:08:00.123 XDES=0x584e1990 lockMode=S schedulerid=7 kpid=10212 status=suspended spid=98 sbid=0 ecid=9 priority=0 transcount=0 lastbatchstarted=2010-09-23T09:08:00.123 lastbatchcompleted=2010-09-23T09:08:00.123 clientapp=.Net SqlClient Data Provider hostname=WEB2 hostpid=4548 isolationlevel=read committed (2) xactid=72110112461 currentdb=17 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
09/23/2010 09:08:00,spid14s,Unknown,executionStack
09/23/2010 09:08:00,spid14s,Unknown,frame procname=dbEPiServer.dbo.netPropertySearchString line=21 stmtstart=1064 stmtend=3640 sqlhandle=0x030011009d4ce3523d5771005d9d00000100000000000000
09/23/2010 09:08:00,spid14s,Unknown,SELECT DISTINCT(tblProperty.fkPageID)<nl/>    FROM       tblProperty<nl/>    INNER JOIN tblPageDefinition ON tblPageDefinition.pkID=tblProperty.fkPageDefinitionID<nl/>    INNER JOIN tblTree ON tblTree.fkChildID=tblProperty.fkPageID<nl/>    INNER JOIN tblPageLanguage ON tblPageLanguage.fkPageID=tblProperty.fkPageID<nl/>    WHERE <nl/>             [email protected] <nl/>    AND [email protected]<nl/>    AND (@LangBranchID=-1 OR [email protected] OR tblPageDefinition.LanguageSpecific=0)<nl/>    AND<nl/>    (<nl/>        (    /*STRING*/<nl/>            Property = 6<nl/>            AND<nl/>            (<nl/>                (@String IS NULL AND String IS NULL)<nl/>                OR<nl/>                String LIKE <nl/>                    CASE    WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=0 THEN @String<nl/>                        WHEN @UseWildCardsBefore=1 AND @UseWildCardsAfter=0 THEN '%' + @String<nl/>                        WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=1 THEN @String + '%'<nl/>                        ELSE '%' + @String + '%'<nl/>                    END<nl/>            )<nl/>        )<nl/>    OR     (    /*LONGSTRING*/<nl/>            Property = 7<nl/>            AND<nl/>            (<nl/>                (@String IS NULL AND @String IS NULL)<nl/>                OR<nl/>                LongString LIKE <nl/>                    CASE    WHEN @
09/23/2010 09:08:00,spid14s,Unknown,inputbuf                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,resource-list                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,objectlock lockPartition=0 objid=1349579846 subresource=FULL dbid=17 objectname=dbEPiServer.dbo.tblProperty id=lock1aec93c0 mode=S associatedObjectId=1349579846
09/23/2010 09:08:00,spid14s,Unknown,owner-list
09/23/2010 09:08:00,spid14s,Unknown,owner id=processc6ab68 mode=S                                                                Property = 6<nl/>            AND<nl/>            (<nl/>                (@String IS NULL AND String IS NULL)<nl/>                OR<nl/>                String LIKE <nl/>                    CASE    WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=0 THEN @String<nl/>                        WHEN @UseWildCardsBefore=1 AND @UseWildCardsAfter=0 THEN '%' + @String<nl/>                        WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=1 THEN @String + '%'<nl/>                        ELSE '%' + @String + '%'<nl/>                    END<nl/>            )<nl/>        )<nl/>    OR     (    /*LONGSTRING*/<nl/>            Property = 7<nl/>            AND<nl/>            (<nl/>                (@String IS NULL AND @String IS NULL)<nl/>                OR<nl/>                LongString LIKE <nl/>                    CASE    WHEN @
09/23/2010 09:08:00,spid14s,Unknown,owner id=processc6ab68 mode=IS
09/23/2010 09:08:00,spid14s,Unknown,waiter-list
09/23/2010 09:08:00,spid14s,Unknown,waiter id=processdac5c8 mode=IX requestType=wait                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,pagelock fileid=1 pageid=726012 dbid=17 objectname=dbEPiServer.dbo.tblPageLanguage id=lock5f275300 mode=IX associatedObjectId=72057594051428352
09/23/2010 09:08:00,spid14s,Unknown,owner-list
09/23/2010 09:08:00,spid14s,Unknown,owner id=processdac5c8 mode=IX                                                            [email protected]<nl/>    /* Move properties from worktable to published table */
09/23/2010 09:08:00,spid14s,Unknown,waiter-list
09/23/2010 09:08:00,spid14s,Unknown,waiter id=process3812c208 mode=S requestType=wait                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,exchangeEvent id=port42c8680 nodeId=26
09/23/2010 09:08:00,spid14s,Unknown,owner-list
09/23/2010 09:08:00,spid14s,Unknown,owner event=e_waitNone type=producer id=process3812c208
09/23/2010 09:08:00,spid14s,Unknown,waiter-list                                                                Property = 6<nl/>            AND<nl/>            (<nl/>                (@String IS NULL AND String IS NULL)<nl/>                OR<nl/>                String LIKE <nl/>                    CASE    WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=0 THEN @String<nl/>                        WHEN @UseWildCardsBefore=1 AND @UseWildCardsAfter=0 THEN '%' + @String<nl/>                        WHEN @UseWildCardsBefore=0 AND @UseWildCardsAfter=1 THEN @String + '%'<nl/>                        ELSE '%' + @String + '%'<nl/>                    END<nl/>            )<nl/>        )<nl/>    OR     (    /*LONGSTRING*/<nl/>            Property = 7<nl/>            AND<nl/>            (<nl/>                (@String IS NULL AND @String IS NULL)<nl/>                OR<nl/>                LongString LIKE <nl/>                    CASE    WHEN @
09/23/2010 09:08:00,spid14s,Unknown,waiter event=e_waitPortClose type=consumer id=process9068e38                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        
 
09/23/2010 09:08:00,spid14s,Unknown,exchangeEvent id=port42c9f80 nodeId=0
09/23/2010 09:08:00,spid14s,Unknown,owner-list
09/23/2010 09:08:00,spid14s,Unknown,owner event=e_waitNone type=producer id=process9068e38
09/23/2010 09:08:00,spid14s,Unknown,waiter-list
09/23/2010 09:08:00,spid14s,Unknown,waiter event=e_waitPortOpen type=consumer id=processc6ab68

So looking at the errors, we are doing a number of property searches (FindPagesWithCriteria), that acquire a shared lock on the rows, as well as a page publish, that tries to acquire an exclusive lock.

Having A = processc6ab68, B = process9068e38, C = process3812c208, D = processdac5c8, where D is the page publish and A, B and C are FindPagesWithCriteria running in parallel.

we can see that A is waiting for B which in turn is waiting for C which is waiting for D which is waiting for A… and the deadlock resolution victim was C, causing our page load failure.

The culprit of this situation was a long running job that was reading pages and publishing them in new language branches on a (high traffic) web site that has a large number of property searches.

A number of things can be done to resolve or at least mitigate this problem such as refactor the property searches to run under a specific language branch, run the job at a period of low traffic or even run the job with the web site in “maintenance” mode.