Uploaded image for project: 'Nuxeo Platform'
  1. Nuxeo Platform
  2. NXP-11475

Deadlock while executing updateReadAcls

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Blocker
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 5.6.0-HF16, 5.7.1
    • Component/s: Core VCS

      Description

      We observed a deadlock while creating two documents concurrently on SQL Server.

      Thread 1: (state = IN_NATIVE)
 - java.net.SocketInputStream.socketRead0(java.io.FileDescriptor, byte[], int, int, int) @bci=0 (Compiled frame; information may be imprecise)
 - java.net.SocketInputStream.read(byte[], int, int, int) @bci=79 (Compiled frame)
 - java.net.SocketInputStream.read(byte[], int, int) @bci=11 (Compiled frame)
 - java.io.DataInputStream.readFully(byte[], int, int) @bci=34 (Compiled frame)
 - java.io.DataInputStream.readFully(byte[]) @bci=5 (Compiled frame)
 - net.sourceforge.jtds.jdbc.SharedSocket.readPacket(byte[]) @bci=8, line=842 (Interpreted frame)
 - net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(int, byte[]) @bci=120, line=723 (Compiled frame)
 - net.sourceforge.jtds.jdbc.ResponseStream.getPacket() @bci=41, line=466 (Compiled frame)
 - net.sourceforge.jtds.jdbc.ResponseStream.read() @bci=12, line=103 (Compiled frame)
 - net.sourceforge.jtds.jdbc.ResponseStream.peek() @bci=1, line=88 (Compiled frame)
 - net.sourceforge.jtds.jdbc.TdsCore.wait(int) @bci=30, line=3932 (Compiled frame)
 - net.sourceforge.jtds.jdbc.TdsCore.executeSQL(java.lang.String, java.lang.String, net.sourceforge.jtds.jdbc.ParamInfo[], boolean, int, int, int, boolean) @bci=432, line=1046 (Compiled frame)
 - net.sourceforge.jtds.jdbc.JtdsStatement.executeSQL(java.lang.String, java.lang.String, net.sourceforge.jtds.jdbc.ParamInfo[], boolean, boolean, boolean) @bci=116, line=537 (Interpreted frame)
 - net.sourceforge.jtds.jdbc.JtdsStatement.executeImpl(java.lang.String, int, boolean) @bci=264, line=723 (Interpreted frame)
 - net.sourceforge.jtds.jdbc.JtdsStatement.execute(java.lang.String) @bci=8, line=1160 (Interpreted frame)
 - net.sourceforge.jtds.jdbcx.proxy.StatementProxy.execute(java.lang.String) @bci=9, line=287 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.jdbc.JDBCMapper.updateReadAcls() @bci=133, line=1038 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SoftRefCachingMapper.updateReadAcls() @bci=4, line=117 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SessionImpl.updateReadAcls() @bci=4, line=1141 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SessionImpl.doFlush() @bci=57, line=334 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SessionImpl.flush() @bci=22, line=321 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SessionImpl.save() @bci=5, line=307 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl.save() @bci=4, line=176 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.coremodel.SQLSession.save() @bci=4, line=149 (Interpreted frame)
 - org.nuxeo.ecm.core.api.AbstractSession.save() @bci=12, line=1838 (Interpreted frame)

      Thread 2: (state = BLOCKED)
 - org.nuxeo.ecm.core.storage.sql.jdbc.JDBCMapper.updateReadAcls() @bci=131, line=1038 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SoftRefCachingMapper.updateReadAcls() @bci=4, line=117 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SessionImpl.updateReadAcls() @bci=4, line=1141 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SessionImpl.doFlush() @bci=57, line=334 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SessionImpl.flush() @bci=22, line=321 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.SessionImpl.save() @bci=5, line=307 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl.save() @bci=4, line=176 (Interpreted frame)
 - org.nuxeo.ecm.core.storage.sql.coremodel.SQLSession.save() @bci=4, line=149 (Interpreted frame)
 - org.nuxeo.ecm.core.api.AbstractSession.save() @bci=12, line=1838 (Interpreted frame)

      What's going on is:

      • thread 1 saves some stuff (which causes locks to be set in the database)
      • thread 2 saves some stuff
      • thread 2 calls updateReadAcls (which is Java synchronized)
      • thread 2 updateReadAcls is blocked by locks set on some rows/tables (to be determined) by thread 1
      • thread 1 calls updateReadAcls and is blocked by the Java synchronization

      -> deadlock

      Note that moving the Java synchronization higher (at save() for instance) wouldn't solve anything, as there may be multiple saves in a single transaction.

        Attachments

          Issue Links

          is required by

          Bug - A problem which impairs or prevents the functions of the product. NXP-14386 Fix infinite 'Skipping updateReadAcls after 2s due to lock' logging

          • Major - Major loss of function.
          • Resolved

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: