Direct links to fixes
APAR status
Closed as program error.
Error description
The problem manifests in threads hanging on the IBM BPM server, as shown in the following traces. Those threads wait to get the necessary lock resources on the database side. The longer the deadlock exists, the more threads wait for the necessary resource leading to hanging process steps in the UI. On the database side, the transaction log shows transactions that have been hanging for a long time but don't get rolled back because they remain connected to a thread on the IBM BPM server side. When there are two threads, one calling setUserAttributes and the other calling getUserAttributes on the same user ID, these two threads could block each other, which requires you to end the database transaction on the setUserAttributes call that is running an UPDATE or INSERT query to unblock. The database shows that there are fetch cursors for the query: SELECT usr_attr_def.NAME AS NAME, attrs.attr_value AS value, usr_attr_def_values.value AS defvalue FROM lsw_usr_attr attrs LEFT JOIN lsw_rt_user_attribute_def rt_usr_attr_def ON attrs.user_attr_def_id = rt_usr_attr_def.user_attribute_id LEFT JOIN lsw_user_attribute_def usr_attr_def ON rt_usr_attr_def.user_attribute_id = usr_attr_def.user_attribute_id LEFT JOIN lsw_user_attr_def_values usr_attr_def_values ON usr_attr_def_values.user_attr_def_value_id = attrs.user_attr_def_value_id AND usr_attr_def_values.user_attribute_def_id = usr_attr_def.user_attribute_id WHERE attrs.user_id = §P0 AND rt_usr_attr_def.NAME = §P1 ORDER BY rt_usr_attr_def.last_modified These cursors are blocked by either INSERT INTO lsw_usr_attr ( user_attr_id, attr_value, attr_number_value, user_id, user_attr_def _value_id, user_attr_def_id ) or by UPDATE lsw_usr_attr SET attr_value =?, attr_number_value = ?, user_id = ?, user_attr_def_value_id = ?, user_attr_def_id = ? WHERE user_attr_id = ? . The SystemOut.log file shows the WSVR0605W message for a thread in a call to getUserAttributes WSVR0605W: Thread "WebContainer : 52" (000075dc) has been active for 1033540 milliseconds and may be hung. There is/are 1 thread(s) in total in the server that may be hung. at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:140) at com.microsoft.sqlserver.jdbc.TDSChannel.read (IOBuffer.java:1647) at com.microsoft.sqlserver.jdbc.TDSReader.readPacket (IOBuffer.java:3694) at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse (IOBuffer.java:5026) at com.microsoft.sqlserver.jdbc.SQLServerResultSet$ CursorFetchCommand.doExecute(SQLServerResultSet.java:4812) at com.microsoft.sqlserver.jdbc.TDSCommand.execute (IOBuffer.java:4575) at com.microsoft.sqlserver.jdbc.SQLServerConnection. executeCommand(SQLServerConnection.java:1400) at com.microsoft.sqlserver.jdbc.SQLServerStatement. executeCommand(SQLServerStatement.java:179) at com.lombardisoftware.utility.spring. ProgrammaticTransactionSupport.executeInExistingTransaction (ProgrammaticTransactionSupport.java:582) at com.lombardisoftware.utility.spring. ProgrammaticTransactionSupport.execute (ProgrammaticTransactionSupport.java:296) at com.lombardisoftware.utility.spring.TransactionInterceptor. invoke(TransactionInterceptor.java:71) at org.springframework.aop.framework. ReflectiveMethodInvocation.proceed (ReflectiveMethodInvocation.java:171) at com.lombardisoftware.utility.spring.CoreEntryInterceptor. invoke(CoreEntryInterceptor.java:44) at com.lombardisoftware.utility.spring.PSCoreEntryInterceptor. invoke(PSCoreEntryInterceptor.java:14) at org.springframework.aop.framework. ReflectiveMethodInvocation.proceed (ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.JdkDynamicAopProxy. invoke(JdkDynamicAopProxy.java:204) at com.sun.proxy.$Proxy33.findByFilter(Unknown Source) at com.lombardisoftware.client.delegate. PersistenceServicesDelegateDefault.findByFilter (PersistenceServicesDelegateDefault.java:414) at com.lombardisoftware.client.persistence. UserAttributeFactory.findByUser(UserAttributeFactory.java:63) at com.lombardisoftware.userorg.UserOrgModule. getUserAttributes(UserOrgModule.java:732) at com.lombardisoftware.server.ejb.security.SecurityCore. getUserAttributes(SecurityCore.java:925) and for the setUserAttributes call WSVR0605W: Thread "WebContainer : 34" (00003919) has been active for 1033368 milliseconds and may be hung. There is/are 2 thread(s) in total in the server that may be hung. at com.lombardisoftware.servlet.util.ProfileCache. getCacheData(ProfileCache.java:99) at com.lombardisoftware.servlet.util.ProfileCache. getProfile(ProfileCache.java:87) at com.lombardisoftware.server.ejb.security.SecurityCore. setUserAttributes(SecurityCore.java:1016) A JavaCore taken when the WSVR0605W message is logged shows these thread stacks: - For the getUserAttributes call, it runs a query because of a getUserAttributes call. This query is blocked because the row lock it needs is held by WebContainer : 13 (the thread running setUserAttributes). 3XMTHREADINFO "WebContainer : 13" J9VMThread:0x0000000007104C00, j9thread_t:0x0000000020B44520, java/lang/Thread:0x000000061A537CE0, state:B, prio=5 3XMJAVALTHREAD (java/lang/Thread getId:0x31F, isDaemon:true) 3XMTHREADINFO1 (native thread ID:0x1124, native priority:0x5, native policy:UNKNOWN) 3XMCPUTIME CPU usage total: 579.933717500 secs, user: 561.166797200 secs, system: 18.766920300 secs 3XMTHREADBLOCK Blocked on: java/lang/Object§0x00000006372CA448 Owned by: "WebContainer : 3" (J9VMThread:0x00000000041E8C00, java/lang/Thread:0x0000000613FC1378) 3XMHEAPALLOC Heap bytes allocated since last GC cycle=0 (0x0) 3XMTHREADINFO3Java callstack: 4XESTACKTRACE at com/lombardisoftware/servlet/util/ProfileCache. getCacheData(ProfileCache.java:99(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/servlet/util/ProfileCache. getProfile(ProfileCache.java:87(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/server/ejb/security/ SecurityCore.setUserAttributes(SecurityCore.java:1016 (Compiled Code)) 5XESTACKTRACE (entered lock: java/lang/String§0x000000067BBF1DC0,entry count: 1) 4XESTACKTRACE at sun/reflect/GeneratedMethodAccessor249. invoke(Bytecode PC:50(Compiled Code)) 4XESTACKTRACE at sun/reflect/DelegatingMethodAccessorImpl. invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code)) 4XESTACKTRACE at java/lang/reflect/Method.invoke(Method. java:611(Compiled Code)) 4XESTACKTRACE at org/springframework/aop/support/AopUtils. invokeJoinpointUsingReflection(AopUtils.java:310 (CompiledCode)) 4XESTACKTRACE at org/springframework/aop/framework/ ReflectiveMethodInvocation.invokeJoinpoint (ReflectiveMethodInvocation.java:182(Compiled Code)) 4XESTACKTRACE at org/springframework/aop/framework/ ReflectiveMethodInvocation.proceed (ReflectiveMethodInvocation.java:149(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/utility/spring/ TransactionInterceptor$2.call(TransactionInterceptor.java:73 (Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/utility/spring/ ProgrammaticTransactionSupport$1.doInTransaction (ProgrammaticTransactionSupport.java:409(Compiled Code)) 4XESTACKTRACE at org/springframework/transaction/jta/ WebSphereUowTransactionManager$UOWActionAdapter.run (WebSphereUowTransactionManager.java:306(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/uow/EmbeddableUOWManagerImpl. runUnderNewUOW(EmbeddableUOWManagerImpl.java:787 (Compiled Code)) 4XESTACKTRACE at com/ibm/ws/uow/EmbeddableUOWManagerImpl. runUnderUOW(EmbeddableUOWManagerImpl.java:366(Compiled Code)) 4XESTACKTRACE at org/springframework/transaction/jta/ WebSphereUowTransactionManager.execute (WebSphereUowTransactionManager.java:252(CompiledCode)) 4XESTACKTRACE at com/lombardisoftware/utility/spring/ ProgrammaticTransactionSupport.executeInNewTransaction (ProgrammaticTransactionSupport.java:404(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/utility/spring/ ProgrammaticTransactionSupport.execute (ProgrammaticTransactionSupport.java:267(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/utility/spring/ TransactionInterceptor.invoke(TransactionInterceptor.java:71 (Compiled Code)) 4XESTACKTRACE at org/springframework/aop/framework/ ReflectiveMethodInvocation.proceed (ReflectiveMethodInvocation.java:171(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/utility/spring/ CoreEntryInterceptor.invoke(CoreEntryInterceptor.java:44 (Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/utility/spring/ PSCoreEntryInterceptor.invoke(PSCoreEntryInterceptor.java:14 (Compiled Code)) 4XESTACKTRACE at org/springframework/aop/framework/ ReflectiveMethodInvocation.proceed (ReflectiveMethodInvocation.java:171(Compiled Code)) 4XESTACKTRACE at org/springframework/aop/framework/ JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204 (Compiled Code)) 4XESTACKTRACE at com/sun/proxy/$Proxy53.setUserAttributes (Bytecode PC:22(Compiled Code)) - The thread in the setUserAttributes call is blocked by WebContainer thread 3, which holds the synchronization lock it needs. WebContainer thread 3 already sent its request to the SQL Server and waits for the response. On the SQL Server side, the transaction waits for the exclusive write lock that is held by the transaction from the setUserAttributes thread (WebContainer thread 13) that won't complete because of the Java lock necessary for finishing the work. 3XMTHREADINFO "WebContainer : 3" J9VMThread:0x00000000041E8C00, j9thread_t:0x0000000000B98740, java/lang/Thread:0x0000000613FC1378, state:R, prio=5 3XMJAVALTHREAD (java/lang/Thread getId:0xDF, isDaemon:true) 3XMTHREADINFO1 (native thread ID:0x19B8, native priority:0x5, native policy:UNKNOWN) 3XMCPUTIME CPU usage total: 561.494399300 secs, user: 536.300237800 secs, system: 25.194161500 secs 3XMHEAPALLOC Heap bytes allocated since last GC cycle=0 (0x0) 3XMTHREADINFO3Java callstack: 4XESTACKTRACE at java/net/SocketInputStream.socketRead0 (Native Method) 4XESTACKTRACE at java/net/SocketInputStream.read (SocketInputStream.java:140(Compiled Code)) 4XESTACKTRACE at com/microsoft/sqlserver/jdbc/TDSChannel.read (IOBuffer.java:1647(Compiled Code)) 4XESTACKTRACE at com/microsoft/sqlserver/jdbc/TDSReader. readPacket(IOBuffer.java:3694(Compiled Code)) 5XESTACKTRACE (entered lock: com/microsoft/sqlserver/jdbc/ TDSReader§0x00000006372CA168, entry count: 1) 4XESTACKTRACE at com/microsoft/sqlserver/jdbc/TDSCommand. startResponse(IOBuffer.java:5026(Compiled Code)) 4XESTACKTRACE at com/microsoft/sqlserver/jdbc/ SQLServerResultSet$CursorFetchCommand.doExecute (SQLServerResultSet.java:4812(Compiled Code)) 4XESTACKTRACE at com/microsoft/sqlserver/jdbc/TDSCommand. execute(IOBuffer.java:4575(Compiled Code)) 4XESTACKTRACE at com/microsoft/sqlserver/jdbc/ SQLServerConnection.executeCommand(SQLServerConnection. java:1400(Compiled Code)) 5XESTACKTRACE (entered lock:java/lang/ Object§0x0000000649D562D8, entry count: 1) 4XESTACKTRACE at com/microsoft/sqlserver/jdbc/ SQLServerStatement.executeCommand(SQLServerStatement. java:179(Compiled Code)) 4XESTACKTRACE at com/microsoft/sqlserver/jdbc/ SQLServerResultSet.doServerFetch(SQLServerResultSet. java:4849(Compiled Code)) 4XESTACKTRACE at com/microsoft/sqlserver/jdbc/ SQLServerResultSet.next(SQLServerResultSet. java:979(Compiled Code)) 4XESTACKTRACE at com/ibm/ws/rsadapter/jdbc/WSJdbcResultSet.next (WSJdbcResultSet.java:3120(Compiled Code)) 4XESTACKTRACE at org/springframework/jdbc/core/ RowMapperResultSetExtractor.extractData (RowMapperResultSetExtractor.java:91(Compiled Code)) 4XESTACKTRACE at org/springframework/jdbc/core/JdbcTemplate$1. doInPreparedStatement(JdbcTemplate.java:653(Compiled Code)) 4XESTACKTRACE at org/springframework/jdbc/core/JdbcTemplate. execute(JdbcTemplate.java:591(Compiled Code)) 4XESTACKTRACE at org/springframework/jdbc/core/JdbcTemplate. query(JdbcTemplate.java:641(Compiled Code)) 4XESTACKTRACE at org/springframework/jdbc/core/JdbcTemplate. query(JdbcTemplate.java:670(Compiled Code)) 4XESTACKTRACE at org/springframework/jdbc/core/JdbcTemplate. query(JdbcTemplate.java:678(Compiled Code)) 4XESTACKTRACE at org/springframework/jdbc/core/JdbcTemplate. query(JdbcTemplate.java:710(Compiled Code)) 4XESTACKTRACE at org/springframework/jdbc/core/simple/ SimpleJdbcTemplate.query(SimpleJdbcTemplate. java:187(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/server/ejb/persistence/ dao/UnversionedPODAO.findOrdered(UnversionedPODAO. java:232(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/server/ejb/persistence/ dao/UnversionedPODAO.findOrdered(UnversionedPODAO. java:203(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/server/ejb/persistence/ dao/UnversionedPODAO.find(UnversionedPODAO. java:199(Compiled Code)) 4XESTACKTRACE at com/lombardisoftware/server/ejb/persistence/ dao/UserAttributeDAO.findByFilter(UserAttributeDAO. java:44(Compiled Code)) ... 25 more lines
Local fix
Problem summary
This problem occurs when two or more threads work on the user attributes of the same user (identical user ID). One of the threads wants to change attributes while the other reads the attributes for further processing. A race condition results where the read thread acquires a lock in the Java code while the write thread acquires an exclusive write lock on the SQL Server database. The read thread acquires the Java lock but can't complete its work because it needs access to rows in the database, which are locked on the database side by the write thread.
Problem conclusion
A fix is/will be available for IBM BPM V8.0.1.3 that changes the locking behavior so that the deadlock situation caused by the race condition no longer occurs by applying read locks to read-only methods and write locks. The write locks prevent other threads from stepping into the critical code block that caused the deadlock situation. On Fix Central (http://www.ibm.com/support/fixcentral), search for JR53192: - Select IBM Business Process Manager with your edition from the product selector, the installed version to the fix pack level, and your platform, and then click Continue. - Select APAR or SPR, enter JR53192, and click Continue. When you download fix packages, ensure that you also download the readme file for each fix. Review each readme file for additional installation instructions and information about the fix.
Temporary fix
Not applicable
Comments
APAR Information
APAR number
JR53192
Reported component name
BPM ADVANCED
Reported component ID
5725C9400
Reported release
801
Status
CLOSED PER
PE
NoPE
HIPER
NoHIPER
Special Attention
NoSpecatt / Xsystem
Submitted date
2015-04-24
Closed date
2015-06-24
Last modified date
2016-05-20
APAR is sysrouted FROM one or more of the following:
APAR is sysrouted TO one or more of the following:
Fix information
Fixed component name
BPM STANDARD
Fixed component ID
5725C9500
Applicable component levels
R801 PSY
UP
[{"Business Unit":{"code":"BU053","label":"Cloud & Data Platform"},"Product":{"code":"SSFTDH","label":"IBM Business Process Manager Standard"},"Platform":[{"code":"PF025","label":"Platform Independent"}],"Version":"8.0.1","Line of Business":{"code":"LOB45","label":"Automation"}}]
Document Information
Modified date:
16 October 2021