On Thu, Dec 22, 2016 at 9:28 AM, Ekku Laukkarinen <ekku....@gmail.com>
wrote:
> Hello,
>
> I recently loaded ~3000 pages into my XWiki (8.2.1) instance. And noticed a
> enormous increase in loading times of DocumentTree in my custom navigation
> panel, which shows the pages under first level of space hierarchy:
>
> #set( $root = $doc.getDocumentReference().getSpaceReferences().get(0).
> toString().replaceAll('([~"])', '~$1').replace("Space ", "document:") +
> ".WebHome")
> {{documentTree showTranslations="false" root="$root" showRoot="true"
> showAttachments="false" /}}
>
> Before loading the pages each request took around ~600ms. After adding the
> pages load time was around 15 seconds. After bit of googling I found the
> JIRA issue:
> http://jira.xwiki.org/browse/XWIKI-13700
> <http://jira.xwiki.org/browse/XWIKI-13700>
>
> And decided to upgrade to 8.4.3. However, the issue did not get fixed and
> there was no change in load times. Turning on debug prints for hibernate
> resulted in the following:
>
>
> 2016-12-21 16:07:36,479 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.i.SessionImpl
>
This is not the URL that the document tree is using in version 8.4.3. It
seems your upgrade is not complete. Did you went through the Distribution
Wizard to upgrade the UI (i.e. the wiki pages)? You should check if the
code of the XWiki.DocumentTreeMacros page corresponds with what you get by
default on 8.4.3. Also, it doesn't hurt to clear the browser cache after an
upgrade.
Hope this helps,
Marius
> - opened session at timestamp: 14823292564
>
> 2016-12-21 16:07:36,479 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.t.JDBCTransaction
> - begin
>
> 2016-12-21 16:07:36,479 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.j.ConnectionManager
> - opening JDBC connection
>
> 2016-12-21 16:07:36,479 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.t.JDBCTransaction
> - current autocommit status: false
>
> 2016-12-21 16:07:36,479 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] INFO o.h.d.Dialect
> - Using dialect: org.hibernate.dialect.HSQLDialect
>
> 2016-12-21 16:07:36,480 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.l.Loader
> - loading entity: [com.xpn.xwiki.doc.XWikiDocument#-
> 4652072126019899209]
>
> 2016-12-21 16:07:36,480 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.j.AbstractBatcher
> - about to open PreparedStatement (open PreparedStatements: 0,
> globally: 0)
>
> 2016-12-21 16:07:36,480 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.SQL
> - select xwikidocum0_.XWD_ID as XWD1_0_0_, xwikidocum0_.XWD_FULLNAME
> as XWD2_0_0_, xwikidocum0_.XWD_NAME as XWD3_0_0_, xwikidocum0_.XWD_TITLE as
> XWD4_0_0_, xwikidocum0_.XWD_LANGUAGE as XWD5_0_0_,
> xwikidocum0_.XWD_DEFAULT_LANGUAGE
> as XWD6_0_0_, xwikidocum0_.XWD_TRANSLATION as XWD7_0_0_,
> xwikidocum0_.XWD_DATE as XWD8_0_0_, xwikidocum0_.XWD_CONTENT_UPDATE_DATE
> as
> XWD9_0_0_, xwikidocum0_.XWD_CREATION_DATE as XWD10_0_0_,
> xwikidocum0_.XWD_AUTHOR as XWD11_0_0_, xwikidocum0_.XWD_CONTENT_AUTHOR as
> XWD12_0_0_, xwikidocum0_.XWD_CREATOR as XWD13_0_0_, xwikidocum0_.XWD_WEB as
> XWD14_0_0_, xwikidocum0_.XWD_CONTENT as XWD15_0_0_,
> xwikidocum0_.XWD_VERSION as XWD16_0_0_, xwikidocum0_.XWD_CUSTOM_CLASS as
> XWD17_0_0_, xwikidocum0_.XWD_PARENT as XWD18_0_0_,
> xwikidocum0_.XWD_CLASS_XML as XWD19_0_0_, xwikidocum0_.XWD_ELEMENTS as
> XWD20_0_0_, xwikidocum0_.XWD_DEFAULT_TEMPLATE as XWD21_0_0_,
> xwikidocum0_.XWD_VALIDATION_SCRIPT as XWD22_0_0_, xwikidocum0_.XWD_COMMENT
> as XWD23_0_0_, xwikidocum0_.XWD_MINOREDIT as XWD24_0_0_,
> xwikidocum0_.XWD_SYNTAX_ID as XWD25_0_0_, xwikidocum0_.XWD_HIDDEN as
> XWD26_0_0_ from xwikidoc xwikidocum0_ where xwikidocum0_.XWD_ID=?
>
> 2016-12-21 16:07:36,480 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.j.AbstractBatcher
> - about to open ResultSet (open ResultSets: 0, globally: 0)
>
> 2016-12-21 16:07:36,480 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.j.AbstractBatcher
> - about to close ResultSet (open ResultSets: 1, globally: 1)
>
> 2016-12-21 16:07:36,480 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.j.AbstractBatcher
> - about to close PreparedStatement (open PreparedStatements: 1,
> globally: 1)
>
> 2016-12-21 16:07:36,480 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG
> h.e.StatefulPersistenceContext - initializing non-lazy collections
>
> 2016-12-21 16:07:36,480 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] DEBUG o.h.l.Loader
> - done entity load
>
> 2016-12-21 16:07:36,481 [http://192.168.42.174/xwiki/
> bin/get/XWiki/DocumentTree?outputSyntax=plain&root=
> document%3Axwiki%3A2987218.WebHome&showAttachments=false&showRoot=true&
> showTranslations=false&root=document%3Axwiki%3A2987218.
> WebHome&showRoot=true&data=children&id=%23] INFO
> h.e.d.DefaultLoadEventListener - Error performing load command
>
> org.hibernate.ObjectNotFoundException: No row with the given identifier
> exists: [com.xpn.xwiki.doc.XWikiDocument#-4652072126019899209]
>
> at org.hibernate.impl.SessionFactoryImpl$2.handleEntityNotFound(
> SessionFactoryImpl.java:435)
>
> at org.hibernate.event.def.DefaultLoadEventListener.load(
> DefaultLoadEventListener.java:233)
>
> at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(
> DefaultLoadEventListener.java:285)
>
> at org.hibernate.event.def.DefaultLoadEventListener.onLoad(
> DefaultLoadEventListener.java:152)
>
> at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1090)
>
> at org.hibernate.impl.SessionImpl.load(SessionImpl.java:974)
>
> at com.xpn.xwiki.store.XWikiHibernateStore.loadXWikiDoc(
> XWikiHibernateStore.java:873)
>
> at com.xpn.xwiki.store.XWikiCacheStore.loadXWikiDoc(
> XWikiCacheStore.java:299)
>
> at com.xpn.xwiki.XWiki.getDocument(XWiki.java:1736)
>
> at com.xpn.xwiki.XWiki.getDocument(XWiki.java:1787)
>
> at com.xpn.xwiki.doc.XWikiDocument.getTranslatedDocument(
> XWikiDocument.java:6146)
>
> at com.xpn.xwiki.doc.XWikiDocument.getTranslatedDocument(
> XWikiDocument.java:6127)
>
> at com.xpn.xwiki.doc.XWikiDocument.getTranslatedDocument(
> XWikiDocument.java:6110)
>
> at com.xpn.xwiki.XWiki.prepareDocuments(XWiki.java:4866)
>
> at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:348)
>
> at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:193)
>
> at org.apache.struts.action.RequestProcessor.processActionPerform(
> RequestProcessor.java:425)
>
> at org.apache.struts.action.RequestProcessor.process(
> RequestProcessor.java:228)
>
> at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1913)
>
> at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:449)
>
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
>
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
>
> at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
>
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.
> doFilter(ServletHandler.java:1669)
>
> at com.xpn.xwiki.web.ActionFilter.doFilter(ActionFilter.java:115)
>
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.
> doFilter(ServletHandler.java:1652)
>
> at org.xwiki.wysiwyg.server.filter.ConversionFilter.
> doFilter(ConversionFilter.java:127)
>
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.
> doFilter(ServletHandler.java:1652)
>
> at org.xwiki.container.servlet.filters.internal.
> SetHTTPHeaderFilter.doFilter(SetHTTPHeaderFilter.java:63)
>
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.
> doFilter(ServletHandler.java:1652)
>
> at org.xwiki.container.servlet.filters.internal.
> SavedRequestRestorerFilter.
> doFilter(SavedRequestRestorerFilter.java:208)
>
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.
> doFilter(ServletHandler.java:1652)
>
> at org.xwiki.container.servlet.filters.internal.
> SetCharacterEncodingFilter.
> doFilter(SetCharacterEncodingFilter.java:111)
>
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.
> doFilter(ServletHandler.java:1652)
>
> at org.xwiki.resource.servlet.RoutingFilter.doFilter(
> RoutingFilter.java:137)
>
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.
> doFilter(ServletHandler.java:1652)
>
> at org.eclipse.jetty.servlet.ServletHandler.doHandle(
> ServletHandler.java:585)
>
> at org.eclipse.jetty.server.handler.ScopedHandler.handle(
> ScopedHandler.java:143)
>
> at org.eclipse.jetty.security.SecurityHandler.handle(
> SecurityHandler.java:577)
>
> at org.eclipse.jetty.server.session.SessionHandler.
> doHandle(SessionHandler.java:223)
>
> at org.eclipse.jetty.server.handler.ContextHandler.
> doHandle(ContextHandler.java:1127)
>
> at org.eclipse.jetty.servlet.ServletHandler.doScope(
> ServletHandler.java:515)
>
> at org.eclipse.jetty.server.session.SessionHandler.
> doScope(SessionHandler.java:185)
>
> at org.eclipse.jetty.server.handler.ContextHandler.
> doScope(ContextHandler.java:1061)
>
> at org.eclipse.jetty.server.handler.ScopedHandler.handle(
> ScopedHandler.java:141)
>
> at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(
> ContextHandlerCollection.java:215)
>
> at org.eclipse.jetty.server.handler.HandlerCollection.
> handle(HandlerCollection.java:110)
>
> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(
> HandlerWrapper.java:97)
>
> at org.eclipse.jetty.server.Server.handle(Server.java:499)
>
> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
>
> at org.eclipse.jetty.server.HttpConnection.onFillable(
> HttpConnection.java:257)
>
> at org.eclipse.jetty.io.AbstractConnection$2.run(
> AbstractConnection.java:540)
>
> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(
> QueuedThreadPool.java:635)
>
> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(
> QueuedThreadPool.java:555)
>
> at java.lang.Thread.run(Thread.java:745)
>
>
>
>
> *org.hibernate.ObjectNotFoundException: No row with the given identifier
> exists: [com.xpn.xwiki.doc.XWikiDocument#-8266574047497816716]*So my guess
> is that hibernate fails to load the entities and has to load each entity
> multiple times? Is this result of a corrupt database due upgrade or
> something else? This error repeats multiple times for each DocumentTree
> loading ( and also some other resources ).
>
> I have also tried to increase the amount of documents cached.
>
> Any help is appreciated.
>
> - Ekku Laukkarinen
>
