Details

      Description

      Reproduction steps:

      1. Generate approximately 100.000 dlfileentry and dlfolder
        or you can use my database and document library where approximately 70.000 entries are created: \r2d2\ftp\Tibi\schneiderspice100\
      2. Start upgrade to 7.0 with latest fixpack

      Results:
      It seems the verify process is stuck as it's so slow, thread dump shows that it's still in progress.

      "pool-7-thread-9" #157 prio=5 os_prio=0 tid=0x00007f1ebd035800 nid=0x6bbc runnable [0x00007f1dd7dfd000]
         java.lang.Thread.State: RUNNABLE
      	at java.net.SocketInputStream.socketRead0(Native Method)
      	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
      	at java.net.SocketInputStream.read(SocketInputStream.java:170)
      	at java.net.SocketInputStream.read(SocketInputStream.java:141)
      	at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
      	at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
      	at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
      	- locked <0x0000000549367a18> (a com.mysql.jdbc.util.ReadAheadInputStream)
      	at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3049)
      	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3503)
      	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3492)
      	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4043)
      	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2503)
      	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2664)
      	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2794)
      	- locked <0x0000000549367a68> (a com.mysql.jdbc.JDBC4Connection)
      	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
      	- locked <0x0000000549367a68> (a com.mysql.jdbc.JDBC4Connection)
      	at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2322)
      	- locked <0x0000000549367a68> (a com.mysql.jdbc.JDBC4Connection)
      	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
      	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
      	at com.liferay.portal.verify.VerifyResourcePermissions._verifyResourcedModel(VerifyResourcePermissions.java:238)
      	at com.liferay.portal.verify.VerifyResourcePermissions.access$100(VerifyResourcePermissions.java:52)
      	at com.liferay.portal.verify.VerifyResourcePermissions$VerifyResourcedModelCallable.call(VerifyResourcePermissions.java:274)
      	at com.liferay.portal.verify.VerifyResourcePermissions$VerifyResourcedModelCallable.call(VerifyResourcePermissions.java:270)
      	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	at java.lang.Thread.run(Thread.java:745)
      

      This thread lives for hours. If you check VerifyResourcePermissions.java:238 you can see that it's executing a created query:
      ResultSet rs = ps.executeQuery()) {
      The query is created here: VerifyResourcePermissions._getVerifyResourcedModelSQL
      I think this query is not effective and the slow query logs states as well:

      select Layout.plid, Layout.userId, ResourcePermission.resourcePermissionId from Layout left join ResourcePermission on (ResourcePermission.companyId = 10401 and ResourcePermission.name = 'com.liferay.portal.kernel.model.Layout' and ResourcePermission.scope = 4 and ResourcePermission.primKey = Layout.plid and ResourcePermission.roleId = 10410) where Layout.companyId = 10401 and ResourcePermission.resourcePermissionId is NULL;
      # Time: 2018-05-03T21:21:21.266026Z
      # User@Host: SEPMIG[SEPMIG] @ localhost [127.0.0.1]  Id:    42
      # Query_time: 33565.196403  Lock_time: 0.000346 Rows_sent: 1  Rows_examined: 14754508547
      SET timestamp=1525382481;
      select count(*) from DLFileEntry left join ResourcePermission on (ResourcePermission.companyId = 10401 and ResourcePermission.name = 'com.liferay.document.library.kernel.model.DLFileEntry' and ResourcePermission.scope = 4 and ResourcePermission.primKey = DLFileEntry.fileEntryId and ResourcePermission.roleId = 10410) where DLFileEntry.companyId = 10401 and ResourcePermission.resourcePermissionId is NULL;
      # Time: 2018-05-03T22:47:19.542863Z
      # User@Host: SEPMIG[SEPMIG] @ localhost [127.0.0.1]  Id:    11
      # Query_time: 38723.468562  Lock_time: 0.000263 Rows_sent: 1  Rows_examined: 16892184602
      SET timestamp=1525387639;
      select count(*) from DLFolder left join ResourcePermission on (ResourcePermission.companyId = 10401 and ResourcePermission.name = 'com.liferay.document.library.kernel.model.DLFolder' and ResourcePermission.scope = 4 and ResourcePermission.primKey = DLFolder.folderId and ResourcePermission.roleId = 10410) where DLFolder.companyId = 10401 and ResourcePermission.resourcePermissionId is NULL;
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                sharry.shi Sharry Shi
                Reporter:
                norbert.kocsis Norbert Kocsis
                Participants of an Issue:
                Recent user:
                Csaba Turcsan
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Days since last comment:
                  1 year, 14 weeks, 4 days ago

                  Packages

                  Version Package
                  7.0.0 DXP FP51
                  7.0.0 DXP SP9
                  7.0.X
                  7.1.X
                  Master