VerifyResourcePermissions is very slow

• Type: Bug
• Status: Closed
• Resolution: Fixed
• Affects Version/s: 7.0.X, Master
• Fix Version/s: 7.0.0 DXP FP51, 7.0.0 DXP SP9, 7.0.X, 7.1.X, Master
• Component/s: Database Upgrade Framework
• Labels:
  • 7.1-won't
  • 7.1UPGRADE-PERFORMANCE
  • QA-NA
  • ee-ts
  • liferay-dxp-70-sp9
  • liferay-fixpack-de-51-7010
• Branch Version/s:
  7.0.x
• Backported to Branch:
  Committed
• Story Points: 12
• Fix Priority: 5
• Git Pull Request: https://github.com/brianchandotcom/liferay-portal/pull/60172

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
# [email protected]: 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
# [email protected]: 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;