-
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
-
Branch Version/s:7.0.x
-
Backported to Branch:Committed
-
Story Points:12
-
Fix Priority:5
-
Git Pull Request:
Reproduction steps:
- 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\ - 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;
- is duplicated by
-
LPS-80766 Upgrade Hangs on VerifyResourcePermissions
- Closed