none
Multiple Runbook server - SQL Deadlocks in RunbookInstanceInputParameters RRS feed

  • Question

  • Hello,

    after installing 2 additional Runbook server we encountered the problem that the different server lock themselves. In there logfiles of the RunBook.exe the following message is found:

    2019-09-30 14:16:47 [2524] 1 Exception caught in long __stdcall WorkflowContextComAdapter::OnPolicyInstanceCreated(unsigned long,wchar_t *)
    WorkflowContextComAdapter.cpp(499):
    <Exception>
    <Type>Opalis::Exception</Type>
    <Location>
    void __cdecl StorageCallExecutor::throwChained(const class Opalis::Exception &)
    StorageCallExecutor.cpp(42)
    </Location>
    <MsgCode>SCE: ActionServerStorage call failed</MsgCode>
    <Prev><Exception>
    <Type>Opalis::Exception</Type>
    <Location>
    void __thiscall ActionServerStorageDB::createPolicyInstance(const class std::basic_string<wchar_t,struct std::char_traits<wchar_t>,class std::allocator<wchar_t> > &,const class std::basic_string<wchar_t,struct std::char_traits<wchar_t>,class std::allocator<wchar_t> > &,const __int64 &,const unsigned long)
    ActionServerStorageDB.cpp(262)
    </Location>
    <MsgCode>createPolicyInstance failed</MsgCode>
    <Params>
    <Param>{1D03A665-C26C-4ABC-9F21-272664E7B6C5}</Param>
    <Param>{097735AA-4EF8-4B6D-A072-80C17C693440}</Param>
    </Params>
    <Prev><Exception>
    <Type>Opalis::Exception</Type>
    <Location>
    void __thiscall CODBDataStore::createPolicyInstance(const class std::basic_string<wchar_t,struct std::char_traits<wchar_t>,class std::allocator<wchar_t> > &,const class std::basic_string<wchar_t,struct std::char_traits<wchar_t>,class std::allocator<wchar_t> > &,const class std::basic_string<wchar_t,struct std::char_traits<wchar_t>,class std::allocator<wchar_t> > &,__int64,unsigned long)
    ODBDataStore.cpp(8199)
    </Location>
    <MsgCode>_com_error</MsgCode>
    <Params>
    <Param>IDispatch error #3092</Param>
    <Param>Error 1205, Level 13, State 52, Procedure InsertRunbookInstanceInputParameters, Line 42, Message: Transaction (Process ID 103) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.</Param>
    <Param>-2147217900</Param>
    </Params>
    </Exception></Prev>
    </Exception></Prev>
    </Exception>

    And here is the deadlock graph from the eventlog of the SQL:


    Here the deadlock as XML:

    <deadlock>
     <victim-list>
      <victimProcess id="process1ced9ad5c28" />
     </victim-list>
     <process-list>
      <process id="process1ced9ad5c28" taskpriority="0" logused="1196" waitresource="PAGE: 5:1:2264337 " waittime="1001" ownerId="1029937" transactionname="INSERT" lasttranstarted="2019-09-30T14:16:46.603" XDES="0x1ceea707310" lockMode="IX" schedulerid="4" kpid="5816" status="suspended" spid="103" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2019-09-30T14:16:46.603" lastbatchcompleted="2019-09-30T14:16:46.603" lastattention="1900-01-01T00:00:00.603" clientapp="Orchestrator" hostname="SERVER01" hostpid="3420" loginname="DOMAIN\m_scorch_admin" isolationlevel="read committed (2)" xactid="1029937" currentdb="5" currentdbname="Orchestrator" lockTimeout="4294967295" clientoption1="673316896" clientoption2="128056">
       <executionStack>
        <frame procname="Orchestrator.Microsoft.SystemCenter.Orchestrator.Runtime.Internal.InsertRunbookInstanceInputParameters" line="42" stmtstart="2196" stmtend="2974" sqlhandle="0x03000500101485515a2ca3002ba8000001000000000000000000000000000000000000000000000000000000">
    INSERT INTO [Microsoft.SystemCenter.Orchestrator.Runtime.Internal].[RunbookInstanceInputParameters] ([RunbookInstanceId], [RunbookParameterId], [Value])
    			SELECT @RunbookInstanceId, rbkParam.[Id], st.[Value] 
    			FROM #sourceTable st 
    			INNER JOIN [Microsoft.SystemCenter.Orchestrator].[RunbookParameters] rbkParam ON rbkParam.[Id] = st.[ID] 
    			WHERE rbkParam.[RunbookId] = @RunbookI    </frame>
        <frame procname="Orchestrator.dbo.OnInsertPolicyInstance" line="27" stmtstart="1522" stmtend="1810" sqlhandle="0x03000500d7ef9050572ca3002ba8000000000000000000000000000000000000000000000000000000000000">
    EXEC [Microsoft.SystemCenter.Orchestrator.Runtime.Internal].[InsertRunbookInstanceInputParameters] @RunbookInstanceId, @RunbookId, @ParametersXm    </frame>
        <frame procname="adhoc" line="1" stmtstart="166" stmtend="398" sqlhandle="0x020000005bad3f3b8cea2bfa9719b99258528a84a7a0fe060000000000000000000000000000000000000000">
    unknown    </frame>
        <frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
    unknown    </frame>
       </executionStack>
       <inputbuf>
    (@P1 uniqueidentifier,@P2 uniqueidentifier,@P3 uniqueidentifier,@P4 int,@P5 bigint)INSERT INTO dbo.POLICYINSTANCES (UniqueID, PolicyID, ActionServer, ProcessID, SeqNumber) VALUES (@P1,@P2,@P3,@P4,@P5)   </inputbuf>
      </process>
      <process id="process1cecaeec4e8" taskpriority="0" logused="2280" waitresource="PAGE: 5:1:2180261 " waittime="216" ownerId="1029887" transactionname="DELETE" lasttranstarted="2019-09-30T14:16:46.560" XDES="0x1cee5f6ce80" lockMode="U" schedulerid="8" kpid="3720" status="suspended" spid="107" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2019-09-30T14:16:46.563" lastbatchcompleted="2019-09-30T14:16:46.560" lastattention="1900-01-01T00:00:00.560" clientapp="Orchestrator" hostname="SERVER02" hostpid="6584" loginname="DOMAIN\m_scorch_admin" isolationlevel="read committed (2)" xactid="1029887" currentdb="5" currentdbname="Orchestrator" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
       <executionStack>
        <frame procname="adhoc" line="1" stmtstart="30" stmtend="132" sqlhandle="0x02000000e3257339269073381748cd63b342ff7d08bea0830000000000000000000000000000000000000000">
    unknown    </frame>
        <frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
    unknown    </frame>
       </executionStack>
       <inputbuf>
    (@P1 nchar(38))DELETE FROM dbo.POLICYINSTANCES where UniqueID = @P1   </inputbuf>
      </process>
     </process-list>
     <resource-list>
      <pagelock fileid="1" pageid="2264337" dbid="5" subresource="FULL" objectname="Orchestrator.Microsoft.SystemCenter.Orchestrator.Runtime.Internal.RunbookInstanceInputParameters" id="lock1cd96678900" mode="U" associatedObjectId="72057594062045184">
       <owner-list>
        <owner id="process1cecaeec4e8" mode="U" />
       </owner-list>
       <waiter-list>
        <waiter id="process1ced9ad5c28" mode="IX" requestType="wait" />
       </waiter-list>
      </pagelock>
      <pagelock fileid="1" pageid="2180261" dbid="5" subresource="FULL" objectname="Orchestrator.Microsoft.SystemCenter.Orchestrator.Runtime.Internal.RunbookInstanceInputParameters" id="lock1cd9639a200" mode="IX" associatedObjectId="72057594062045184">
       <owner-list>
        <owner id="process1ced9ad5c28" mode="IX" />
       </owner-list>
       <waiter-list>
        <waiter id="process1cecaeec4e8" mode="U" requestType="wait" />
       </waiter-list>
      </pagelock>
     </resource-list>
    </deadlock>

    Systeminfos:
    Orchestrator 2019 RTM
    Windows Server 2016 (1607)
    SQL Server 2016 SP2 CU8

    Does someone have any info regarding this on how to solve this?

    Thanks in advance
    Paulo


    • Edited by PauloW4 Monday, September 30, 2019 12:53 PM
    Monday, September 30, 2019 12:48 PM

Answers

  • Hello,

    for those that encounter this problem. We seem to have figured it out.
    The problem was that the database was too big (~50GB!). According to various sources online this should never be.
    The Log Purge taks seems to have been too much for the server or more specifically the storage hosting the DB. The Disk Queue Length reached 6000!

    After checking I found out that the tables "OBJECTINSTANCES" and "OBJECTINSTANCEDATA" were the cause. The had millions of entries, which seem to not be removed.

    Further research lead me to truncating the tables and shrinking the DB:
    truncate table OBJECTINSTANCES
    truncate table OBJECTINSTANCEDATA

    The DB is now ~2,2GB in size and the new Log Purge tasks seem to be working and keeping the tables cleaned.

    Cheers
    Paul
    • Marked as answer by PauloW4 Tuesday, October 8, 2019 8:37 AM
    Tuesday, October 8, 2019 8:37 AM