Major Description
On XWiki 16.4.6 I noticed the following behaviour:
While doing some large amount of operations involving replacing pages, the thread doing the work was often found with the following stacktrace in the mysql dump:
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.Net.poll(Native Method)
at sun.nio.ch.NioSocketImpl.park(NioSocketImpl.java:186)
at sun.nio.ch.NioSocketImpl.park(NioSocketImpl.java:195)
at sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:319)
at sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:355)
at sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:808)
at java.net.Socket$SocketInputStream.read(Socket.java:966)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:244)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
at java.io.BufferedInputStream.read(BufferedInputStream.java:343)
- locked on java.io.BufferedInputStream@4e7fd986
at org.mariadb.jdbc.client.socket.impl.PacketReader.readReusablePacket(PacketReader.java:62)
at org.mariadb.jdbc.message.ClientMessage.readPacket(ClientMessage.java:164)
at org.mariadb.jdbc.client.impl.StandardClient.readPacket(StandardClient.java:1246)
at org.mariadb.jdbc.client.impl.StandardClient.readResults(StandardClient.java:1185)
at org.mariadb.jdbc.client.impl.StandardClient.readResponse(StandardClient.java:1104)
at org.mariadb.jdbc.client.impl.StandardClient.execute(StandardClient.java:1028)
at org.mariadb.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:101)
at org.mariadb.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:323)
at org.mariadb.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:300)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:137)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:137)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:137)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:197)
at org.hibernate.hql.internal.ast.exec.BasicExecutor.doExecute(BasicExecutor.java:80)
at org.hibernate.hql.internal.ast.exec.BasicExecutor.execute(BasicExecutor.java:50)
at org.hibernate.hql.internal.ast.exec.DeleteExecutor.execute(DeleteExecutor.java:177)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:458)
at org.hibernate.engine.query.spi.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:376)
at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1483)
at org.hibernate.query.internal.AbstractProducedQuery.doExecuteUpdate(AbstractProducedQuery.java:1714)
at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1696)
at com.xpn.xwiki.store.XWikiHibernateStore.lambda$deleteLinks$20(XWikiHibernateStore.java:2360)
at com.xpn.xwiki.store.XWikiHibernateStore$$Lambda$2614/0x00007fc7cdade560.doInHibernate()
at com.xpn.xwiki.store.XWikiHibernateBaseStore.execute(XWikiHibernateBaseStore.java:826)
at com.xpn.xwiki.store.XWikiHibernateBaseStore.executeWrite(XWikiHibernateBaseStore.java:948)
at com.xpn.xwiki.store.XWikiHibernateStore.deleteLinks(XWikiHibernateStore.java:2356)
at com.xpn.xwiki.store.XWikiHibernateStore.deleteXWikiDoc(XWikiHibernateStore.java:1244)
at com.xpn.xwiki.store.XWikiHibernateStore.deleteXWikiDoc(XWikiHibernateStore.java:1205)
at com.xpn.xwiki.store.XWikiCacheStore.deleteXWikiDoc(XWikiCacheStore.java:435)
at com.xpn.xwiki.XWiki.deleteDocument(XWiki.java:4633)
at com.xpn.xwiki.XWiki.saveDocument(XWiki.java:2082)
at com.xpn.xwiki.internal.filter.output.DocumentInstanceOutputFilterStream.maybeSaveDocument(DocumentInstanceOutputFilterStream.java:252)
at com.xpn.xwiki.internal.filter.output.DocumentInstanceOutputFilterStream.endWikiDocumentRevision(DocumentInstanceOutputFilterStream.java:164)
[...]
In the database, when showing the full process list, the delete from xwikilinks based on a value of the xwl_doc_id column was appearing very often upon subsequent calls (which is a sign that the system is spending a lot of time in this function).
The xwikilinks table has no indexes:
MariaDB [xwiki]> show indexes from xwikilinks; +------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+ | Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment | +------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+ | xwikilinks | 0 | PRIMARY | 1 | XWL_ID | A | 1834874 | NULL | NULL | | BTREE | | | +------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+ 1 row in set (0.017 sec)
A slow delete filtered by a column that is not indexed makes a lot of sense, and there is no good reason for this table to not be indexed.