Ticket #1216 (assigned defect)

Opened 16 months ago

Last modified 9 months ago

ONE homepage timeout

Reported by: rcave Owned by: rcave
Priority: high Milestone:
Component: ambra Version: 0.9.1_rc1
Keywords: Cc:

Description

Trying to bring up the ONE homepage on the demo site results in a Mulgara query timeout. This is not caused by xpub'd articles as before. The error is: 

2009-03-22 14:45:49,848 ERROR UnhandledException(PLoSONE)> error performing query 'select a.id id, dc.date date, dc.title title, ci, (select a.articleType from Article aa) at, (select aa2.id rid, aa2.dublinCore.title rtitle from Article aa2    where aa2 = a.relatedArticles.article) relatedArticles, (select fc from FormalCorrection fc where fc.annotates = a.id) corrections, (select r from Retraction r where r.annotates = a.id) retractions from Article a, CitationInfo ci where a.id = :id and dc := a.dublinCore and ci.id = dc.bibliographicCitation.id;' [TP-Processor3 org.topazproject.ambra.UnhandledException]
org.topazproject.otm.query.QueryException: error performing query 'select a.id id, dc.date date, dc.title title, ci, (select a.articleType from Article aa) at, (select aa2.id rid, aa2.dublinCore.title rtitle from Article aa2    where aa2 = a.relatedArticles.article) relatedArticles, (select fc from FormalCorrection fc where fc.annotates = a.id) corrections, (select r from Retraction r where r.annotates = a.id) retractions from Article a, CitationInfo ci where a.id = :id and dc := a.dublinCore and ci.id = dc.bibliographicCitation.id;'
        at org.topazproject.otm.stores.ItqlStore.doQuery(ItqlStore.java:851)
        at org.topazproject.otm.impl.QueryImpl.execute(QueryImpl.java:86)
        at org.topazproject.otm.impl.SessionImpl.loadView(SessionImpl.java:755)
        at org.topazproject.otm.impl.SessionImpl.getFromStore(SessionImpl.java:649)
        at org.topazproject.otm.impl.SessionImpl.get(SessionImpl.java:382)
        at org.topazproject.otm.impl.SessionImpl.get(SessionImpl.java:345)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:296)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:177)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:166)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at $Proxy0.get(Unknown Source)
        at org.topazproject.ambra.article.service.BrowseService.loadArticleInfo(BrowseService.java:504)
        at org.topazproject.ambra.article.service.BrowseService.access$600(BrowseService.java:72)
        at org.topazproject.ambra.article.service.BrowseService$5.lookup(BrowseService.java:633)
        at org.topazproject.ambra.article.service.BrowseService$5.lookup(BrowseService.java:632)
        at org.topazproject.ambra.cache.EhcacheProvider$1.execute(EhcacheProvider.java:123)
        at org.topazproject.ambra.cache.Cache$SynchronizedLookup.execute(Cache.java:220)
        at org.topazproject.ambra.cache.EhcacheProvider.get(EhcacheProvider.java:113)
        at org.topazproject.ambra.article.service.BrowseService.getArticleInfo(BrowseService.java:629)
        at org.topazproject.ambra.article.service.BrowseService.loadArticles(BrowseService.java:608)
        at org.topazproject.ambra.article.service.BrowseService.getArticlesByDate(BrowseService.java:239)
        at org.topazproject.ambra.article.service.BrowseService$$FastClassByCGLIB$$a555f0d8.invoke(<generated>)
        at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191)
        at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:695)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:166)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:630)
        at org.topazproject.ambra.article.service.BrowseService$$EnhancerByCGLIB$$7a594fa9.getArticlesByDate(<generated>)
        at org.topazproject.ambra.action.HomePageAction.initRecentArticles(HomePageAction.java:154)
        at org.topazproject.ambra.action.HomePageAction.execute(HomePageAction.java:189)
        at org.topazproject.ambra.action.HomePageAction$$FastClassByCGLIB$$1673b5a.invoke(<generated>)
        at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191)
        at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:695)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:166)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:630)
        at org.topazproject.ambra.action.HomePageAction$$EnhancerByCGLIB$$62cb593f.execute(<generated>)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at com.opensymphony.xwork2.DefaultActionInvocation.invokeAction(DefaultActionInvocation.java:404)
        at com.opensymphony.xwork2.DefaultActionInvocation.invokeActionOnly(DefaultActionInvocation.java:267)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:229)
        at org.topazproject.ambra.struts2.TransactionInterceptor.intercept(TransactionInterceptor.java:61)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at org.topazproject.ambra.user.EnsureUserAccountInterceptor.intercept(EnsureUserAccountInterceptor.java:65)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at org.topazproject.ambra.user.UserAccountsInterceptor.intercept(UserAccountsInterceptor.java:102)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at org.topazproject.ambra.journal.SessionFiltersInterceptor.intercept(SessionFiltersInterceptor.java:51)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.DefaultWorkflowInterceptor.doIntercept(DefaultWorkflowInterceptor.java:221)
        at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:86)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.validator.ValidationInterceptor.doIntercept(ValidationInterceptor.java:150)
        at org.apache.struts2.interceptor.validation.AnnotationValidationInterceptor.doIntercept(AnnotationValidationInterceptor.java:48)
        at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:86)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.ConversionErrorInterceptor.intercept(ConversionErrorInterceptor.java:123)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.ParametersInterceptor.doIntercept(ParametersInterceptor.java:184)
        at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:86)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.StaticParametersInterceptor.intercept(StaticParametersInterceptor.java:105)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at org.apache.struts2.interceptor.FileUploadInterceptor.intercept(FileUploadInterceptor.java:207)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.ModelDrivenInterceptor.intercept(ModelDrivenInterceptor.java:74)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at org.apache.struts2.interceptor.debugging.DebuggingInterceptor.intercept(DebuggingInterceptor.java:206)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.I18nInterceptor.intercept(I18nInterceptor.java:143)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.PrepareInterceptor.doIntercept(PrepareInterceptor.java:121)
        at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:86)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at org.apache.struts2.interceptor.ServletConfigInterceptor.intercept(ServletConfigInterceptor.java:170)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.AliasInterceptor.intercept(AliasInterceptor.java:123)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.LoggingInterceptor.intercept(LoggingInterceptor.java:52)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.TimerInterceptor.invokeUnderTiming(TimerInterceptor.java:125)
        at com.opensymphony.xwork2.interceptor.TimerInterceptor.intercept(TimerInterceptor.java:112)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at com.opensymphony.xwork2.interceptor.ExceptionMappingInterceptor.intercept(ExceptionMappingInterceptor.java:176)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:224)
        at com.opensymphony.xwork2.DefaultActionInvocation$2.doProfiling(DefaultActionInvocation.java:223)
        at com.opensymphony.xwork2.util.profiling.UtilTimerStack.profile(UtilTimerStack.java:455)
        at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:221)
        at org.apache.struts2.impl.StrutsActionProxy.execute(StrutsActionProxy.java:50)
        at org.apache.struts2.dispatcher.Dispatcher.serviceAction(Dispatcher.java:504)
        at org.apache.struts2.dispatcher.FilterDispatcher.doFilter(FilterDispatcher.java:419)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.mortbay.servlet.UserAgentFilter.doFilter(UserAgentFilter.java:81)
        at org.mortbay.servlet.GzipFilter.doFilter(GzipFilter.java:145)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.topazproject.ambra.web.DummySSOFilter.doFilter(DummySSOFilter.java:128)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.topazproject.ambra.web.VirtualJournalContextFilter.doFilter(VirtualJournalContextFilter.java:150)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:164)
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:141)
        at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:90)
        at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:406)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.topazproject.ambra.web.MultipleRequestFilter.doFilter(MultipleRequestFilter.java:95)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
        at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:773)
        at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703)
        at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:895)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
        at java.lang.Thread.run(Thread.java:619)
Caused by: java.io.IOException: Error running query 'select $a $date $title $ci subquery(select $oqltmp1_0 from <local:///topazproject#filter:graph=ri> where $aa <rdf:type> <http://rdf.topazproject.org/RDF/Article> in <local:///topazproject#filter:graph=ri> and $a <http://www.w3.org/1999/02/22-rdf-syntax-ns#type> $oqltmp1_0 in <local:///topazproject#filter:graph=ri> and ($oqltmp3_1_0_o0_f0_0_0_ <http://purl.org/dc/terms/hasPart> $aa in <local:///topazproject#filter:graph=ri> and $oqltmp3_1_0_o0_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/25b76621-a502-46dc-9ab9-501ae9e3f9f3> or $aa <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>)) subquery(select $aa2 $rtitle from <local:///topazproject#filter:graph=ri> where $aa2 <rdf:type> <http://rdf.topazproject.org/RDF/Article> in <local:///topazproject#filter:graph=ri> and $a <http://rdf.plos.org/RDF/relatedArticle> $oqltmp2_3 in <local:///topazproject#filter:graph=ri> and $oqltmp2_3 <http://purl.org/dc/terms/references> $aa2 in <local:///topazproject#filter:graph=ri> and ($oqltmp3_2_1_o0_f0_0_0_ <http://purl.org/dc/terms/hasPart> $aa2 in <local:///topazproject#filter:graph=ri> and $oqltmp3_2_1_o0_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/25b76621-a502-46dc-9ab9-501ae9e3f9f3> or $aa2 <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>) and $aa2 <http://purl.org/dc/elements/1.1/title> $rtitle in <local:///topazproject#filter:graph=ri> and ($oqltmp3_2_0_o0_f0_0_0_ <http://purl.org/dc/terms/hasPart> $aa2 in <local:///topazproject#filter:graph=ri> and $oqltmp3_2_0_o0_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/25b76621-a502-46dc-9ab9-501ae9e3f9f3> or $aa2 <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>)) subquery(select $fc from <local:///topazproject#filter:graph=ri> where $fc <rdf:type> <http://rdf.topazproject.org/RDF/2008/01/annotationType#FormalCorrection> in <local:///topazproject#filter:graph=ri> and $fc <http://www.w3.org/2000/10/annotation-ns#annotates> $a in <local:///topazproject#filter:graph=ri>) subquery(select $r from <local:///topazproject#filter:graph=ri> where $r <rdf:type> <http://rdf.topazproject.org/RDF/2008/01/annotationType#Retraction> in <local:///topazproject#filter:graph=ri> and $r <http://www.w3.org/2000/10/annotation-ns#annotates> $a in <local:///topazproject#filter:graph=ri>) from <local:///topazproject#filter:graph=ri> where $a <rdf:type> <http://rdf.topazproject.org/RDF/Article> in <local:///topazproject#filter:graph=ri> and $ci <rdf:type> <http://purl.org/net/nknouf/ns/bibtex#Entry> in <local:///topazproject#filter:graph=ri> and $a <mulgara:is> <info:doi/10.1371/journal.pntd.0000392> and $a <http://purl.org/dc/terms/bibliographicCitation> $ci in <local:///topazproject#filter:graph=ri> and $a <http://purl.org/dc/elements/1.1/date> $date in <local:///topazproject#filter:graph=ri> and $a <http://purl.org/dc/elements/1.1/title> $title in <local:///topazproject#filter:graph=ri> and ($oqltmp3_0_0_o0_f0_0_0_ <http://purl.org/dc/terms/hasPart> $a in <local:///topazproject#filter:graph=ri> and $oqltmp3_0_0_o0_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/25b76621-a502-46dc-9ab9-501ae9e3f9f3> or $a <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>);'
        at org.topazproject.mulgara.itql.TIClient.doQuery(TIClient.java:101)
        at org.topazproject.otm.stores.ItqlStore.doQuery(ItqlStore.java:849)
        ... 190 more
Caused by: org.mulgara.query.QueryException: java.lang.IllegalStateException: Transaction was heuristically rolled back. Reason: transaction-timeout
        at org.mulgara.resolver.TransactionalAnswer.getVariables(TransactionalAnswer.java:170)
        at org.mulgara.query.ArrayAnswer.<init>(ArrayAnswer.java:191)
        at org.mulgara.query.ArrayAnswer.<init>(ArrayAnswer.java:207)
        at org.mulgara.server.rmi.SessionWrapperRemoteSession.convertToRemoteAnswer(SessionWrapperRemoteSession.java:640)
        at org.mulgara.server.rmi.SessionWrapperRemoteSession.query(SessionWrapperRemoteSession.java:396)
        at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
        at sun.rmi.transport.Transport$1.run(Transport.java:159)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        at java.lang.Thread.run(Thread.java:619)
        at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:255)
        at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:233)
        at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:142)
        at org.mulgara.server.rmi.RemoteSessionImpl_Stub.query(Unknown Source)
        at org.mulgara.server.rmi.RemoteSessionWrapperSession.query(RemoteSessionWrapperSession.java:541)
        at org.mulgara.query.Query.execute(Query.java:568)
        at org.mulgara.query.Query.execute(Query.java:57)
        at org.topazproject.mulgara.itql.TIClient.doQuery(TIClient.java:82)
        ... 191 more
Caused by: org.mulgara.query.QueryException: org.mulgara.query.TuplesException: Transaction was heuristically rolled back. Reason: transaction-timeout
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at org.mulgara.resolver.MulgaraTransactionFactory.newException(MulgaraTransactionFactory.java:349)
        at org.mulgara.resolver.MulgaraExternalTransaction.checkActive(MulgaraExternalTransaction.java:277)
        at org.mulgara.resolver.MulgaraExternalTransaction.execute(MulgaraExternalTransaction.java:225)
        at org.mulgara.resolver.TransactionalAnswer.getVariables(TransactionalAnswer.java:164)
        at org.mulgara.query.ArrayAnswer.<init>(ArrayAnswer.java:191)
        at org.mulgara.query.ArrayAnswer.<init>(ArrayAnswer.java:207)
        at org.mulgara.server.rmi.SessionWrapperRemoteSession.convertToRemoteAnswer(SessionWrapperRemoteSession.java:640)
        at org.mulgara.server.rmi.SessionWrapperRemoteSession.query(SessionWrapperRemoteSession.java:396)
        at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
        at sun.rmi.transport.Transport$1.run(Transport.java:159)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        ... 1 more

Change History

  Changed 16 months ago by dragisak

That looks like view query in ArticleInfo

follow-up: ↓ 3   Changed 16 months ago by ronald

I've see this sporadically too, and it's due to minor variations in the way the query is processed in mulgara leading to sometimes choosing a very bad join order. Here are two query planner dumps for comparison: 

2009-03-17 16:10:17,640 WARN  HybridTuples> Materialising... [RMI TCP Connection(3293)-207.7.131.23 org.mulgara.store.xa.HybridTuples]
2009-03-17 16:10:18,331 WARN  HybridTuples> Materialising tuples(691) from 
(class org.mulgara.store.tuples.UnorderedProjection<149378308>[~9223372036854775807] {$a, $cat, $date}  
.   (class org.mulgara.store.tuples.UnboundJoin<192839213>[~9223372036854775807] {$a, $oqltmp2_0, $cat, $oqltmp3_0_1_o1_f0_0_0_, $oqltmp3_0_0_o1_f0_0_0_, $date} 
.   .   (class org.mulgara.store.tuples.UnconstrainedTuples<2036206635>[=1] {}) 
.   .   (class org.mulgara.resolver.store.StatementStoreResolution<495829568>[~7405] {$a})
.   .   (class org.mulgara.resolver.store.StatementStoreResolution<1170999016>[~28191] {$a, $oqltmp2_0})
.   .   (class org.mulgara.resolver.store.StatementStoreResolution<1440320804>[~28267] {$oqltmp2_0, $cat})  
.   .   (class org.mulgara.store.tuples.OrderedAppend<1036083844>[~47497] {$a, $oqltmp3_0_1_o1_f0_0_0_} 
.   .   .   (class org.mulgara.store.xa.HybridTuples<1663756232>[=47493] {$a, $oqltmp3_0_1_o1_f0_0_0_}  
.   .   .   .   (class org.mulgara.store.tuples.EmptyTuples<995684858>[=0] {})) 
.   .   .   (class org.mulgara.store.tuples.DistinctTuples<366423637>[~4] {$a, $oqltmp3_0_1_o1_f0_0_0_} 
.   .   .   .   (class org.mulgara.store.xa.HybridTuples<1646451110>[=4] {$a, $oqltmp3_0_1_o1_f0_0_0_} 
.   .   .   .   .   (class org.mulgara.store.tuples.EmptyTuples<995684858>[=0] {}))))
.   .   (class org.mulgara.store.tuples.OrderedAppend<1577014175>[~47497] {$a, $oqltmp3_0_0_o1_f0_0_0_} 
.   .   .   (class org.mulgara.store.xa.HybridTuples<634067951>[=47493] {$a, $oqltmp3_0_0_o1_f0_0_0_}
.   .   .   .   (class org.mulgara.store.tuples.EmptyTuples<995684858>[=0] {}))
.   .   .   (class org.mulgara.store.tuples.DistinctTuples<966196043>[~4] {$a, $oqltmp3_0_0_o1_f0_0_0_}
.   .   .   .   (class org.mulgara.store.xa.HybridTuples<1733039734>[=4] {$a, $oqltmp3_0_0_o1_f0_0_0_}
.   .   .   .   .   (class org.mulgara.store.tuples.EmptyTuples<995684858>[=0] {}))))
.   .   (class org.mulgara.resolver.store.StatementStoreResolution<878105077>[~83052] {$a, $date}))) [RMI TCP Connection(3293)-207.7.131.23 org.mulgara.store.xa.HybridTuples]
2009-03-17 16:10:18,332 DEBUG TuplesOperations> Sorted ... [RMI TCP Connection(3293)-207.7.131.23 org.mulgara.store.tuples.TuplesOperations]
2009-03-17 16:10:18,332 DEBUG TuplesOperations> Sorted 17875 rows [RMI TCP Connection(3293)-207.7.131.23 org.mulgara.store.tuples.TuplesOperations]

2009-03-17 16:43:52,481 WARN  HybridTuples> Materialising... [RMI TCP Connection(3352)-207.7.131.23 org.mulgara.store.xa.HybridTuples]
2009-03-17 16:53:50,540 WARN  HybridTuples> Materialising tuples(598059) from
(class org.mulgara.store.tuples.UnorderedProjection<223271882>[~9223372036854775807] {$a, $cat, $date} 
.   (class org.mulgara.store.tuples.UnboundJoin<876589465>[~9223372036854775807] {$a, $oqltmp2_0, $cat, $date, $oqltmp3_0_1_o0_f0_0_0_, $oqltmp3_0_0_o0_f0_0_0_} 
.   .   (class org.mulgara.store.tuples.UnconstrainedTuples<2036206635>[=1] {})
.   .   (class org.mulgara.resolver.store.StatementStoreResolution<1101319835>[~7405] {$a}) 
.   .   (class org.mulgara.resolver.store.StatementStoreResolution<720913352>[~28191] {$a, $oqltmp2_0}) 
.   .   (class org.mulgara.resolver.store.StatementStoreResolution<287970690>[~28267] {$oqltmp2_0, $cat})
.   .   (class org.mulgara.resolver.store.StatementStoreResolution<1642730139>[~83052] {$a, $date})
.   .   (class org.mulgara.store.tuples.OrderedAppend<1315680341>[~47497] {$oqltmp3_0_1_o0_f0_0_0_, $a} 
.   .   .   (class org.mulgara.store.tuples.DistinctTuples<378028>[~4] {$oqltmp3_0_1_o0_f0_0_0_, $a} 
.   .   .   .   (class org.mulgara.store.xa.HybridTuples<2058549302>[=4] {$oqltmp3_0_1_o0_f0_0_0_, $a} 
.   .   .   .   .   (class org.mulgara.store.tuples.EmptyTuples<995684858>[=0] {}))) 
.   .   .   (class org.mulgara.store.xa.HybridTuples<2076565544>[=47493] {$oqltmp3_0_1_o0_f0_0_0_, $a} 
.   .   .   .   (class org.mulgara.store.tuples.EmptyTuples<995684858>[=0] {})))
.   .   (class org.mulgara.store.tuples.OrderedAppend<2080350611>[~47497] {$oqltmp3_0_0_o0_f0_0_0_, $a}
.   .   .   (class org.mulgara.store.tuples.DistinctTuples<1271462270>[~4] {$oqltmp3_0_0_o0_f0_0_0_, $a}
.   .   .   .   (class org.mulgara.store.xa.HybridTuples<2004084240>[=4] {$oqltmp3_0_0_o0_f0_0_0_, $a}
.   .   .   .   .   (class org.mulgara.store.tuples.EmptyTuples<995684858>[=0] {})))
.   .   .   (class org.mulgara.store.xa.HybridTuples<1510302132>[=47493] {$oqltmp3_0_0_o0_f0_0_0_, $a}
.   .   .   .   (class org.mulgara.store.tuples.EmptyTuples<995684858>[=0] {}))))) [RMI TCP Connection(3352)-207.7.131.23 org.mulgara.store.xa.HybridTuples]
2009-03-17 16:53:50,541 DEBUG TuplesOperations> Sorted ... [RMI TCP Connection(3352)-207.7.131.23 org.mulgara.store.tuples.TuplesOperations]
2009-03-17 16:53:50,541 DEBUG TuplesOperations> Sorted 17875 rows [RMI TCP Connection(3352)-207.7.131.23 org.mulgara.store.tuples.TuplesOperations]

As can be seen, both are very similar and produce the exact same results, but one takes .7s and the other take nearly 600s. The difference a small change in the order of the variables in the top-level join ($date), leading to a slightly different join order with vastly different run times (the OrderedAppend? have their arguments in a different order too, but I believe that makes no noticeable difference).

The corresponding tql queries that ambra/topaz issued were, respectively: 

select $cat $a $date from <local:///topazproject#filter:graph=ri>
  where $a <rdf:type> <http://rdf.topazproject.org/RDF/Article> in <local:///topazproject#filter:graph=ri>
  and
  $a <http://rdf.topazproject.org/RDF/hasCategory> $oqltmp2_0 in <local:///topazproject#filter:graph=ri>
  and
  $oqltmp2_0 <http://rdf.topazproject.org/RDF/mainCategory> $cat in <local:///topazproject#filter:graph=ri>
  and
  (
    $a <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>
    or
    $oqltmp3_0_1_o1_f0_0_0_ <http://purl.org/dc/terms/hasPart> $a in <local:///topazproject#filter:graph=ri>
    and
    $oqltmp3_0_1_o1_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/61cec9c3-10a4-4441-a110-98fb265dc0ac>
  )
  and
  $a <http://purl.org/dc/elements/1.1/date> $date in <local:///topazproject#filter:graph=ri>
  and
  (
    $a <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>
    or
    $oqltmp3_0_0_o1_f0_0_0_ <http://purl.org/dc/terms/hasPart> $a in <local:///topazproject#filter:graph=ri>
    and
    $oqltmp3_0_0_o1_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/61cec9c3-10a4-4441-a110-98fb265dc0ac>
  )
  order by $date desc $a;

select $cat $a $date from <local:///topazproject#filter:graph=ri>
  where $a <rdf:type> <http://rdf.topazproject.org/RDF/Article> in <local:///topazproject#filter:graph=ri>
  and
  $a <http://rdf.topazproject.org/RDF/hasCategory> $oqltmp2_0 in <local:///topazproject#filter:graph=ri>
  and
  $oqltmp2_0 <http://rdf.topazproject.org/RDF/mainCategory> $cat in <local:///topazproject#filter:graph=ri>
  and
  (
    $oqltmp3_0_1_o0_f0_0_0_ <http://purl.org/dc/terms/hasPart> $a in <local:///topazproject#filter:graph=ri>
    and
    $oqltmp3_0_1_o0_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/61cec9c3-10a4-4441-a110-98fb265dc0ac>
    or
    $a <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>
  )
  and
  $a <http://purl.org/dc/elements/1.1/date> $date in <local:///topazproject#filter:graph=ri>
  and
  (
    $oqltmp3_0_0_o0_f0_0_0_ <http://purl.org/dc/terms/hasPart> $a in <local:///topazproject#filter:graph=ri>
    and
    $oqltmp3_0_0_o0_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/61cec9c3-10a4-4441-a110-98fb265dc0ac>
    or
    $a <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>
  )
  order by $date desc $a;

I.e. apart from a trivial variable name change, the only difference is the order of the terms in the disjunctions.

The point is, small, innocuous

in reply to: ↑ 2   Changed 16 months ago by ronald

Replying to ronald:

[snip - accidently hit the submit button]
The point is, small, innocuous

The point is, small, innocuous changes at the tql level can lead to huge query performance differences, which make it very hard generate queries.

  Changed 16 months ago by dragisak

temporary workaround:

PloS ONE had one cross-published article from PNTD. That article shouldn't be there. If you delete that id from PLoS ONE's simple collection, journal filter will be smart enough not to put 'or' clause. Then similar queries will run much faster.

  Changed 16 months ago by dragisak

  • owner changed from dragisak to rich
  • type changed from defect to clarification

  Changed 16 months ago by dragisak

Cross published articles in computational biology on demo: 

select $a
from <local:///topazproject#ri> 
where <info:doi/10.1371/aggregation/9ae656fa-8d5d-43c2-98a3-357199baa043> <http://purl.org/dc/terms/hasPart> $a;

a
---------------------------------------
<info:doi/10.1371/journal.pgen.1000390>
<info:doi/10.1371/journal.pgen.1000410>

To get list of all cross-published articles in the database: 

select $id $title $eIssn $xpubArticle
from <local:///topazproject#ri>
where $id <rdf:type> <http://rdf.plos.org/RDF/Journal>
and $id <dc:title> $title
and $id <http://prismstandard.org/namespaces/1.2/basic/eIssn> $eIssn
and $id <http://purl.org/dc/terms/hasPart> $xpubArticle;

  Changed 16 months ago by dragisak

Another possible workaround until the real fix in Mulgara is in:

Allow per-journal control of how journal filter orders clauses in the query.

So in one case it's: 

$oqltmp3_0_0_o0_f0_0_0_ <http://purl.org/dc/terms/hasPart> $a in <local:///topazproject#filter:graph=ri>
and
$oqltmp3_0_0_o0_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/61cec9c3-10a4-4441-a110-98fb265dc0ac>
or
$a <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>

and in the other case it's: 

$a <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1932-6203' in <local:///topazproject#filter:graph=ri>
or
$oqltmp3_0_0_o0_f0_0_0_ <http://purl.org/dc/terms/hasPart> $a in <local:///topazproject#filter:graph=ri>
and
$oqltmp3_0_0_o0_f0_0_0_ <mulgara:is> <info:doi/10.1371/aggregation/61cec9c3-10a4-4441-a110-98fb265dc0ac>

  Changed 16 months ago by rcave

  • priority changed from critical to high
  • milestone 0.9.2 deleted

Moving out of 0.9.2. We'll need an appropriate fix (either Mulgara or per-journal control of journal filter order clauses) before we create cross journal collections.

  Changed 12 months ago by rcave

  • status changed from new to assigned
  • owner changed from rcave to npeterson

  Changed 10 months ago by npeterson

  • owner changed from npeterson to rcave

This bug should go in Topaz or Mulgara project

  Changed 9 months ago by npeterson

  • type changed from clarification to defect
Note: See TracTickets for help on using tickets.