IndexQueue1 and IndexQueue2 deadlock in the database for Windchill

• IndexQueue1 or IndexQueue2 generates a cluster stack in BackgroundMethodServer log due to SQL exception
• Queues are blocked/slow due to IndexQueue
• Queues are blocked in the executing and ready state
• One IndexQueue will have wt.pds.SQLDatabasePds.handleSQLException:

"IndexQueue2.PollingThread" Id=181 prio=5 RUNNABLE (in native)
      Blocked (cnt): 22653; Waited (cnt): 23359
      CPU nanos: 325531250000; User nanos: 308593750000; Bytes allocated: 129579637296
      Method context: 4eihtrmk;jrf0wyi1;3980;5ydi2x;881070; DB session: 190
      % of 1 CPU used by context: 2.9146476775255348 (46875000/1608256132); Bytes allocated by context: 13757424
  at java.net.SocketInputStream.socketRead0(Native Method)
  at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
  at java.net.SocketInputStream.read(SocketInputStream.java:171)
  at java.net.SocketInputStream.read(SocketInputStream.java:141)
  at wt.util.WrappedSocket$Input.read(WrappedSocket.java:379)
  at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
  at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
    - locked java.io.BufferedInputStream@64780d
  at java.io.DataInputStream.readByte(DataInputStream.java:265)
  at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:222)
  at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:161)
  at com.sun.jmx.remote.internal.PRef.invoke(Unknown Source)
  at javax.management.remote.rmi.RMIConnectionImpl_Stub.invoke(Unknown Source)
  at javax.management.remote.rmi.RMIConnector$RemoteMBeanServerConnection.invoke(RMIConnector.java:1020)
  at javax.management.MBeanServerInvocationHandler.invoke(MBeanServerInvocationHandler.java:298)
  at com.sun.proxy.$Proxy170.getAttributesFromAllClusterMethodServers(Unknown Source)
  at wt.util.jmx.GetClusterStacks.outputClusterStacks(GetClusterStacks.java:75)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:498)
  at wt.pds.SQLDatabasePds.handleSQLException(SQLDatabasePds.java:1222)
  at wt.pds.SQLDatabasePds.processSQLException(SQLDatabasePds.java:4132)
  at wt.pds.SQLDatabasePds.insertList(SQLDatabasePds.java:3237)
  at wt.pds.SQLDatabasePds.insert(SQLDatabasePds.java:306)
  at wt.pom.PersistentObjectManager.insert(PersistentObjectManager.java:2404)
  at wt.pom.PersistentObjectManager.insertUpdate(PersistentObjectManager.java:2322)
  at wt.pom.PersistentObjectManager.insert(PersistentObjectManager.java:598)
  at wt.fc.StandardPersistenceManager$1.doMultiOperation(StandardPersistenceManager.java:1673)
  at wt.fc.WTCollectionRetrySingleProcessor.executeWithRetry(WTCollectionRetrySingleProcessor.java:162)
  at wt.fc.WTCollectionRetrySingleProcessor.execute(WTCollectionRetrySingleProcessor.java:87)
  at wt.fc.StandardPersistenceManager.insert(StandardPersistenceManager.java:1694)
  at wt.fc.StandardPersistenceManager.store(StandardPersistenceManager.java:712)
  at wt.fc.StandardPersistenceManager.store(StandardPersistenceManager.java:1091)
  at wt.fc.StandardPersistenceManager.save(StandardPersistenceManager.java:928)
  at sun.reflect.GeneratedMethodAccessor486.invoke(Unknown Source)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:498)
  at wt.services.ServiceFactory$ServerInvocationHandler.invoke(ServiceFactory.java:399)
  at com.sun.proxy.$Proxy11.save(Unknown Source)
  at wt.index.IndexStatusHelper.updateIndexerSet(IndexStatusHelper.java:217)
  at wt.index.AbstractIndexServiceDelegate.index(AbstractIndexServiceDelegate.java:466)
  at wt.index.IndexingServiceImpl.processIndexRequest(IndexingServiceImpl.java:280)
  at wt.index.StandardIndexPolicyManager.processIndexRequest(StandardIndexPolicyManager.java:387)

• And the other IndexQueue will have wt.index.IndexStatusHelper.updateIndexerSet:

"IndexQueue1.PollingThread" Id=191 prio=5 RUNNABLE (in native)
      Blocked (cnt): 22417; Waited (cnt): 23112
      CPU nanos: 326984375000; User nanos: 311640625000; Bytes allocated: 129347105296
      Method context: 4eihtrmk;jrf0wyi1;3980;5ydi2x;881069; DB session: 177
      % of 1 CPU used by context: 1.9430641127701833 (31250000/1608284554); Bytes allocated by context: 12813432
  at java.net.SocketInputStream.socketRead0(Native Method)
  at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
  at java.net.SocketInputStream.read(SocketInputStream.java:171)
  at java.net.SocketInputStream.read(SocketInputStream.java:141)
  at oracle.net.ns.Packet.receive(Packet.java:311)
  at oracle.net.ns.DataPacket.receive(DataPacket.java:105)
  at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:305)
  at oracle.net.ns.NetInputStream.read(NetInputStream.java:249)
  at oracle.net.ns.NetInputStream.read(NetInputStream.java:171)
  at oracle.net.ns.NetInputStream.read(NetInputStream.java:89)
  at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:123)
  at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:79)
  at oracle.jdbc.driver.T4CMAREngineStream.unmarshalUB1(T4CMAREngineStream.java:426)
  at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:390)
  at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:249)
  at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:566)
  at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:215)
  at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:58)
  at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:943)
  at oracle.jdbc.driver.OraclePreparedStatement.executeForRowsWithTimeout(OraclePreparedStatement.java:10932)
  at oracle.jdbc.driver.OraclePreparedStatement.executeBatch(OraclePreparedStatement.java:11043)
    - locked oracle.jdbc.driver.T4CConnection@706d819c
  at oracle.jdbc.driver.OracleStatementWrapper.executeBatch(OracleStatementWrapper.java:244)
  at wt.pds.SQLDatabasePds.insertList(SQLDatabasePds.java:3201)
  at wt.pds.SQLDatabasePds.insert(SQLDatabasePds.java:306)
  at wt.pom.PersistentObjectManager.insert(PersistentObjectManager.java:2404)
  at wt.pom.PersistentObjectManager.insertUpdate(PersistentObjectManager.java:2322)
  at wt.pom.PersistentObjectManager.insert(PersistentObjectManager.java:598)
  at wt.fc.StandardPersistenceManager$1.doMultiOperation(StandardPersistenceManager.java:1673)
  at wt.fc.WTCollectionRetrySingleProcessor.executeWithRetry(WTCollectionRetrySingleProcessor.java:162)
  at wt.fc.WTCollectionRetrySingleProcessor.execute(WTCollectionRetrySingleProcessor.java:87)
  at wt.fc.StandardPersistenceManager.insert(StandardPersistenceManager.java:1694)
  at wt.fc.StandardPersistenceManager.store(StandardPersistenceManager.java:712)
  at wt.fc.StandardPersistenceManager.store(StandardPersistenceManager.java:1091)
  at wt.fc.StandardPersistenceManager.save(StandardPersistenceManager.java:928)
  at sun.reflect.GeneratedMethodAccessor486.invoke(Unknown Source)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:498)
  at wt.services.ServiceFactory$ServerInvocationHandler.invoke(ServiceFactory.java:399)
  at com.sun.proxy.$Proxy11.save(Unknown Source)
  at wt.index.IndexStatusHelper.updateIndexerSet(IndexStatusHelper.java:217)
  at wt.index.AbstractIndexServiceDelegate.index(AbstractIndexServiceDelegate.java:466)
  at wt.index.IndexingServiceImpl.processIndexRequest(IndexingServiceImpl.java:280)
  at wt.index.StandardIndexPolicyManager.processIndexRequest(StandardIndexPolicyManager.java:387)

• Oracle alert log indicates a deadlock occurred:

ORA-00060: Deadlock detected. See Note 60.1 at My Oracle Support for Troubleshooting ORA-60 Errors. More info in file E:\ORACLE\diag\rdbms\wind\wind\trace\wind_ora_864.trc.

• Session IDs in Oracle trace file match db session in BackgroundMethodServer log
  • wind_ora_864.trc shows session IDs 177 and 190 are deadlocked:

Deadlock graph:
                                          ---------Blocker(s)--------  ---------Waiter(s)---------
Resource Name                             process session holds waits  process session holds waits
TX-000E0010-0001DD9C-00000000-00000000        109     190     X             61     177           S
TX-000D0006-0001BC1C-00000000-00000000         61     177     X            109     190           S

• BackgroundMethodServer log shows DB session: 177 for IndexQueue1:

"IndexQueue1.PollingThread" Id=191 prio=5 RUNNABLE (in native)
      Blocked (cnt): 22417; Waited (cnt): 23112
      CPU nanos: 326984375000; User nanos: 311640625000; Bytes allocated: 129347105296
      Method context: 4eihtrmk;jrf0wyi1;3980;5ydi2x;881069; DB session: 177
BackgroundMethodServer log shows DB session: 190 for IndexQueue2:
"IndexQueue2.PollingThread" Id=181 prio=5 RUNNABLE (in native)
      Blocked (cnt): 22653; Waited (cnt): 23359
      CPU nanos: 325531250000; User nanos: 308593750000; Bytes allocated: 129579637296
      Method context: 4eihtrmk;jrf0wyi1;3980;5ydi2x;881070; DB session: 190

• Oracle trace file shows both deadlocked sessions are currently running the same INSERT statement:

INSERT INTO IndexStatus(classnameA2A2,updateCountA2,batchId,coreName,errorDesc,indexRequestId,indexedObject,indexerSet,status,markForDeleteA2,ufid,verified,updateStampA2,createStampA2,modifyStampA2,idA2A2) VALUES ('wt.index.IndexStatus',1,:1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:9 ,:10 ,:11 ,:12 ,:13 ,:14 )

​​​​​​​