IBM Support

JR53192: MULTIPLE THREADS WORKING ON THE SAME USER ATTRIBUTES CAN CAUSE A DEADLOCK ON SQL SERVER DATABASES

Subscribe

You can track all active APARs for this component.

 

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"},"Component":"","ARM Category":[],"Platform":[{"code":"PF025","label":"Platform Independent"}],"Version":"8.0.1","Edition":"","Line of Business":{"code":"LOB36","label":"IBM Automation"}}]

Document Information

Modified date:
20 May 2016