publishing articles is slow

pubbing today's CB articles gave me the following:

Errors

Exception: org.topazproject.ambra.ApplicationException?: org.topazproject.ambra.ApplicationException?: org.topazproject.otm.query.QueryException?: error performing query 'select id from Article o where id := cast(o, Article).id and id = ;'

Messages

Published: info:doi/10.1371/image.pcbi.v05.i04 Published: info:doi/10.1371/journal.pcbi.1000358 Published: info:doi/10.1371/journal.pcbi.1000359 Published: info:doi/10.1371/journal.pcbi.1000362 Published: info:doi/10.1371/journal.pcbi.1000365 Published: info:doi/10.1371/journal.pcbi.1000367 Published: info:doi/10.1371/journal.pcbi.1000371 Published: info:doi/10.1371/journal.pcbi.1000374 Published: info:doi/10.1371/journal.pcbi.1000375

it tells me everything pubbed, but if i go to browse by pub date there is nothing for 4/24, and search turns nothing up. Going directly to an article gives a site error (though I can view it if I log in).

Same for Gen: " Exception: org.topazproject.ambra.ApplicationException?: org.topazproject.ambra.ApplicationException?: org.topazproject.otm.query.QueryException?: error performing query 'select id from Article o where id := cast(o, Article).id and id = ;'

Messages

Published: info:doi/10.1371/image.pgen.v05.i04 Published: info:doi/10.1371/journal.pgen.1000458 Published: info:doi/10.1371/journal.pgen.1000459 Published: info:doi/10.1371/journal.pgen.1000460 Published: info:doi/10.1371/journal.pgen.1000461 "

possibly relevant: the pub step is taking longer than usual today. 12 minutes to pub 5 Genetics articles.

Looks like the transaction timed out.

*************************************************************************************** Caused by: org.mulgara.query.MulgaraTransactionException?: No externally mediated transaction associated with session - last transaction was rolled back with error: transaction-timeout

at

**************************************************************************************

2009-04-23 15:04:32,011 ERROR BaseAdminActionSupport?(PLoSCompBiol)> Admin console Exception [TP-Processor1176 org.topazproject.ambra.admin.action.BaseAdminActionSupport?] org.topazproject.ambra.ApplicationException?: org.topazproject.ambra.ApplicationException?: org.topazproject.otm.query.QueryException?: error performing query 'select id from Article o where id := cast(o, Article).id and id = <info:doi/10.1371/journal.pcbi.1000365>;' Caused by: org.topazproject.ambra.ApplicationException?: org.topazproject.otm.query.QueryException?: error performing query 'select id from Article o where id:= cast(o, Article).id and id = <info:doi/10.1371/journal.pcbi.1000365>;' Caused by: org.topazproject.otm.query.QueryException?: error performing query 'select id from Article o where id := cast(o, Article).id and id = <info:doi/10.1371/journal.pcbi.1000365>;' Caused by: java.io.IOException: Error running query 'select $o from <local:///topazproject#filter:graph=ri> where $o <rdf:type> <http://rdf.topazproject.org/RDF/Article> in <local:///topazproject#filter:graph=ri> and $o <mulgara:is> <info:doi/10.1371/journal.pcbi.1000365> and $o <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1935-2735' in <local:///topazproject#filter:graph=ri> and $o <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1935-2735' in <local:///topazproject#filter:graph=ri>;' Caused by: org.mulgara.query.QueryException?: Query failed: No externally mediated transaction associated with session - last transaction was rolled back with error: transaction-timeout

full trace follows:

2009-04-23 15:04:32,011 ERROR BaseAdminActionSupport?(PLoSCompBiol)> Admin console Exception [TP-Processor1176 org.topazproject.ambra.admin.action.BaseAdminActionSupport?] org.topazproject.ambra.ApplicationException?: org.topazproject.ambra.ApplicationException?: org.topazproject.otm.query.QueryException?: error performing query 'select id from Article o where id := cast(o, Article).id and id = <info:doi/10.1371/journal.pcbi.1000365>;'

at

org.topazproject.ambra.admin.service.DocumentManagementService?.getPublis hableFiles(DocumentManagementService?.java:352)

at

org.topazproject.ambra.admin.service.DocumentManagementService?$$FastClas? sByCGLIB$$bf95593d.invoke(<generated>)

at net.sf.cglib.proxy.MethodProxy?.invoke(MethodProxy?.java:191)

org.topazproject.ambra.admin.service.DocumentManagementService?$$Enhancer ByCGLIB$$91a173cb.getPublishableFiles(<generated>)

at

org.topazproject.ambra.admin.action.BaseAdminActionSupport?.base(BaseAdmi? nActionSupport.java:46)

at

org.topazproject.ambra.admin.action.PublishArchivesAction?.execute(Publis hArchivesAction.java:69)

at

org.topazproject.ambra.admin.action.PublishArchivesAction?$$FastClassByCG LIB$$cc8b2cff.invoke(<generated>)

at net.sf.cglib.proxy.MethodProxy?.invoke(MethodProxy?.java:191)

org.topazproject.ambra.admin.action.PublishArchivesAction?$$EnhancerByCGL IB$$4d7b17e5.execute(<generated>)

at sun.reflect.NativeMethodAccessorImpl?.invoke0(Native Method)

org.topazproject.ambra.user.EnsureRoleInterceptor?.intercept(EnsureRoleIn? terceptor.java:43)

org.topazproject.ambra.user.EnsureUserAccountInterceptor?.getReturnCodeDe pendingOnDisplayName(EnsureUserAccountInterceptor?.java:101)

at

org.topazproject.ambra.user.EnsureUserAccountInterceptor?.intercept(Ensur eUserAccountInterceptor.java:73)

org.topazproject.ambra.user.UserAccountsInterceptor?.intercept(UserAccoun? tsInterceptor.java:102)

org.topazproject.ambra.journal.SessionFiltersInterceptor?.intercept(Sessi onFiltersInterceptor.java:51)

org.topazproject.ambra.web.DummySSOFilter.doFilter(DummySSOFilter.java:1 05)

Caused by: org.topazproject.ambra.ApplicationException?: org.topazproject.otm.query.QueryException?: error performing query 'select id from Article o where id := cast(o, Article).id and id = <info:doi/10.1371/journal.pcbi.1000365>;'

at

org.topazproject.ambra.article.service.FetchArticleService?.getArticleIds (FetchArticleService?.java:235)

at

org.topazproject.ambra.admin.service.DocumentManagementService?.getPublis hableFiles(DocumentManagementService?.java:347)

... 168 more

Caused by: org.topazproject.otm.query.QueryException?: error performing query 'select id from Article o where id := cast(o, Article).id and id = <info:doi/10.1371/journal.pcbi.1000365>;'

at

org.topazproject.otm.stores.ItqlStore?.doQuery(ItqlStore?.java:851)

at

org.topazproject.otm.impl.QueryImpl?.execute(QueryImpl?.java:86)

at

org.topazproject.ambra.journal.JournalCarrierService?.getObjects(JournalC arrierService.java:169)

at

org.topazproject.ambra.journal.JournalCarrierService?.buildCarrierMap(Jou rnalCarrierService.java:147)

at

org.topazproject.ambra.journal.JournalCarrierService?.access$200(JournalC arrierService.java:56)

at

org.topazproject.ambra.journal.JournalCarrierService?$2.lookup(JournalCar? rierService.java:187)

at

org.topazproject.ambra.journal.JournalCarrierService?$2.lookup(JournalCar? rierService.java:186)

at

org.topazproject.ambra.cache.EhcacheProvider?$1.execute(EhcacheProvider?.j ava:123)

at

org.topazproject.ambra.cache.Cache$SynchronizedLookup?.execute(Cache.java :220)

at

org.topazproject.ambra.cache.EhcacheProvider?.get(EhcacheProvider?.java:11 3)

at

org.topazproject.ambra.journal.JournalCarrierService?.getJournalKeysForOb ject(JournalCarrierService?.java:184)

at

org.topazproject.ambra.journal.JournalCarrierService?.getJournalsForObjec t(JournalCarrierService?.java:198)

at

org.topazproject.ambra.journal.JournalService?.getJournalsForObject(Journ alService.java:163)

at

org.topazproject.ambra.journal.JournalService?$$FastClassByCGLIB$$3e152a5 7.invoke(<generated>)

at net.sf.cglib.proxy.MethodProxy?.invoke(MethodProxy?.java:191)

org.topazproject.ambra.journal.JournalService?$$EnhancerByCGLIB$$dc36c2ad .getJournalsForObject(<generated>)

at

org.topazproject.ambra.article.service.ArticleFeedService?$Invalidator.ma tchesJournal(ArticleFeedService?.java:638)

at

org.topazproject.ambra.article.service.ArticleFeedService?$Invalidator.ma tches(ArticleFeedService?.java:532)

at

org.topazproject.ambra.article.service.ArticleFeedService?$Invalidator.in validateFeedCacheForArticle(ArticleFeedService?.java:478)

at

org.topazproject.ambra.article.service.ArticleFeedService?$Invalidator.ob jectChanged(ArticleFeedService?.java:425)

at

org.topazproject.ambra.cache.CacheManager?.objectChanged(CacheManager?.jav a:163)

at

org.topazproject.ambra.cache.OtmInterceptor?.onPostWrite(OtmInterceptor?.j ava:232)

at

org.topazproject.otm.impl.SessionImpl?.write(SessionImpl?.java:584)

at

org.topazproject.otm.impl.SessionImpl?.doFlush(SessionImpl?.java:167)

at

org.topazproject.otm.impl.SessionImpl?.flush(SessionImpl?.java:131)

at

org.topazproject.otm.impl.QueryImpl?.execute(QueryImpl?.java:81)

at

org.topazproject.ambra.article.service.ArticleOtmService?.getArticleIds(A rticleOtmService.java:246)

at

org.topazproject.ambra.article.service.ArticleOtmService?$$FastClassByCGL IB$$cdd3990.invoke(<generated>)

at net.sf.cglib.proxy.MethodProxy?.invoke(MethodProxy?.java:191)

org.topazproject.ambra.article.service.ArticleOtmService?$$EnhancerByCGLI B$$8eb5fd20.getArticleIds(<generated>)

at

org.topazproject.ambra.article.service.FetchArticleService?.getArticleIds (FetchArticleService?.java:233)

... 169 more

Caused by: java.io.IOException: Error running query 'select $o from <local:///topazproject#filter:graph=ri> where $o <rdf:type> <http://rdf.topazproject.org/RDF/Article> in <local:///topazproject#filter:graph=ri> and $o <mulgara:is> <info:doi/10.1371/journal.pcbi.1000365> and $o <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1935-2735' in <local:///topazproject#filter:graph=ri> and $o <http://prismstandard.org/namespaces/1.2/basic/eIssn> '1935-2735' 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)

... 209 more

Caused by: org.mulgara.query.QueryException?: Query failed: No externally mediated transaction associated with session - last transaction was rolled back with error: transaction-timeout

at

org.mulgara.resolver.DatabaseSession?.execute(DatabaseSession?.java:755)

at

org.mulgara.resolver.DatabaseSession?.query(DatabaseSession?.java:465)

at

org.mulgara.server.rmi.SessionWrapperRemoteSession?.query(SessionWrapperR emoteSession.java:396)

at sun.reflect.GeneratedMethodAccessor?9.invoke(Unknown Source)

org.mulgara.server.rmi.RemoteSessionWrapperSession?.query(RemoteSessionWr? apperSession.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)

... 210 more

*************************************************************************************** Caused by: org.mulgara.query.MulgaraTransactionException?: No externally mediated transaction associated with session - last transaction was rolled back with error: transaction-timeout

at

************************************************************************************** org.mulgara.resolver.MulgaraExternalTransactionFactory?.getTransaction(Mu lgaraExternalTransactionFactory.java:66)

at

org.mulgara.resolver.DatabaseSession?.execute(DatabaseSession?.java:751)

at

org.mulgara.resolver.DatabaseSession?.query(DatabaseSession?.java:465)

at

org.mulgara.server.rmi.SessionWrapperRemoteSession?.query(SessionWrapperR emoteSession.java:396)

at sun.reflect.GeneratedMethodAccessor?9.invoke(Unknown Source)

org.topazproject.ambra.admin.action.PublishArchivesAction?$$EnhancerByCGL IB$$4d7b17e5.execute(<generated>)

at sun.reflect.NativeMethodAccessorImpl?.invoke0(Native Method)

org.topazproject.ambra.user.EnsureUserAccountInterceptor?.getReturnCodeDe pendingOnDisplayName(EnsureUserAccountInterceptor?.java:101)

org.topazproject.ambra.user.EnsureUserAccountInterceptor?.intercept(Ensur eUserAccountInterceptor.java:73)

org.topazproject.ambra.user.UserAccountsInterceptor?.intercept(UserAccoun? tsInterceptor.java:102)

org.topazproject.ambra.journal.SessionFiltersInterceptor?.intercept(Sessi onFiltersInterceptor.java:51)

org.topazproject.ambra.cas.client.filter.CASFilter.doFilter(CASFilter.ja va:319)

org.topazproject.ambra.web.DummySSOFilter.doFilter(DummySSOFilter.java:1 05)

org.topazproject.ambra.web.MultipleRequestFilter?.doFilter(MultipleReques? tFilter.java:95)

Possibly due to Lucene re-index for newly published articles. Can Lucene re-index asynchronously?

Replying to rich:

Possibly due to Lucene re-index for newly published articles. Can Lucene re-index asynchronously?

First of all, stop guessing - it's quite easy to figure out where the time is being spent. Second, there's no indexing happening on publish.

After looking through the logs and doing more research into the incredibly complex piece of code that simply needs to find articles in the DISABLED state (not yet published).

1. By the time this error happens the articles are already published and everything 
is fine.

2. The PublishArchievesAction has a method called base(). One of base()'s jobs is 
to look up all the ready to publish articles and provide that information to the 
freemarker template so the admin will see them on the page.

3. base() invokes getPublishableFiles which looks for all the articles with  state
= Article.STATE_DISABLED. (seems simple enough)

4. During this lookup QueryImpl notices we have just written things (we published) 
and decides to flush.

5. After the write the onPostWrite method of the OtmIntercepter is invoked which 
means all the cache invalidators (note the plural) start getting called. This sets 
off a new round of queries by JournalCarrierService.getJournalKeysForObject.
  
private Set<URI> getObjects(String jName, URI obj, Session s) {
    Set<String> oldFilters = s.listFilters();
    for (String fn : oldFilters)
      s.disableFilter(fn);

    for (String fn : journalFilterService.getFilters(jName, s))
      s.enableFilter(fn);

    Set<URI> res = new HashSet<URI>();

    // XXX: should be "... from Object ..." but filters don't get applied then
    String q = "select id from Article o where id := cast(o, Article).id" +
                (obj != null ? " and id = <" + obj + ">;" : ";");

Which is part of the journal filtering.

6. Eventually one of these queries hangs for some reason and the transaction 
times out and everything gets rolled back even though it was probably published 
correctly in the first place.

7. In the case of this exception the Feed invalidator was getting called. I am 
not sure if it is always the one that causes the problem but we need to check.

Basically this one one action spawns hundreds of queries.