Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Long delay when logging in to populated instance #3885

Closed
brianjlowe opened this issue Jun 6, 2023 · 6 comments · Fixed by vivo-project/Vitro#395
Closed

Long delay when logging in to populated instance #3885

brianjlowe opened this issue Jun 6, 2023 · 6 comments · Fixed by vivo-project/Vitro#395
Assignees
Labels

Comments

@brianjlowe
Copy link
Member

brianjlowe commented Jun 6, 2023

Describe the bug
On VIVO 1.13, after submitting email and password, login takes many seconds to complete and redirect on a populated instance. Approximately 5 seconds on an instance with 10 million triples. Thanks to Michael Bentz for originally reporting this issue on Slack.

To Reproduce

  1. Populate an instance with 10+ million triples.
  2. Log in as root or admin: submit email and password.
  3. Observe long delay before you are redirected to Site Admin.

Environment (please complete the following information):

  • OS: Linux
  • Browser Firefox
  • Tomcat version 9
  • VIVO version 1.13.0
  • Apache Solr
@brianjlowe brianjlowe self-assigned this Jun 6, 2023
@brianjlowe
Copy link
Member Author

Delay is suspiciously similar to the delay incurred in listing the named graphs in use in a TDB instance.

@brianjlowe
Copy link
Member Author

brianjlowe commented Jun 6, 2023

Indeed, grabbing thread dumps during the delays consistently shows calls to getGraphURIs(), which is very slow on TDB. Not sure yet why this is happening on login/logout and not on other requests.

Login example:

"ajp-nio-127.0.0.1-8009-exec-9" #50 daemon prio=5 os_prio=0 cpu=83850.94ms elapsed=610488.84s tid=0x00007fc1d8be4800 nid=0x3460a5 runnable [0x00007fbfe95e5000]
java.lang.Thread.State: RUNNABLE
at java.util.HashMap.hash(java.base@11.0.18/HashMap.java:340)
at java.util.HashMap.put(java.base@11.0.18/HashMap.java:608)
at java.util.HashSet.add(java.base@11.0.18/HashSet.java:220)
at org.apache.jena.atlas.iterator.FilterUnique.test(FilterUnique.java:32)
at org.apache.jena.atlas.iterator.Iter$1.hasNext(Iter.java:228)
at org.apache.jena.atlas.iterator.Iter.hasNext(Iter.java:1067)
at org.apache.jena.atlas.iterator.Iter$2.hasNext(Iter.java:347)
at org.apache.jena.util.iterator.WrappedIterator.hasNext(WrappedIterator.java:90)
at org.apache.jena.util.iterator.MapFilterIterator.hasNext(MapFilterIterator.java:54)
- locked <0x00000007fcd21000> (a org.apache.jena.util.iterator.MapFilterIterator)
at edu.cornell.mannlib.vitro.webapp.rdfservice.impl.jena.RDFServiceJena.getGraphURIs(RDFServiceJena.java:542)
- locked <0x0000000602e4e2f8> (a java.lang.Class for edu.cornell.mannlib.vitro.webapp.rdfservice.impl.jena.RDFServiceJena)
at edu.cornell.mannlib.vitro.webapp.rdfservice.impl.jena.tdb.RDFServiceTDB.getGraphURIs(RDFServiceTDB.java:186)
at edu.cornell.mannlib.vitro.webapp.rdfservice.impl.RDFServiceFactorySingle$UnclosableRDFService.getGraphURIs(RDFServiceFactorySingle.java:130)
at edu.cornell.mannlib.vitro.webapp.rdfservice.impl.logging.LoggingRDFService.getGraphURIs(LoggingRDFService.java:145)
at edu.cornell.mannlib.vitro.webapp.dao.jena.RDFServiceModelMaker.getModelNames(RDFServiceModelMaker.java:72)
at edu.cornell.mannlib.vitro.webapp.dao.jena.RDFServiceModelMaker.listModels(RDFServiceModelMaker.java:86)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.AbstractModelMakerDecorator.listModels(AbstractModelMakerDecorator.java:98)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.AbstractModelMakerDecorator.listModels(AbstractModelMakerDecorator.java:98)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.ModelMakerWithPersistentEmptyModels.listModels(ModelMakerWithPersistentEmptyModels.java:49)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.AbstractModelMakerDecorator.listModels(AbstractModelMakerDecorator.java:98)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.NamedDefaultModelMaker.listModels(NamedDefaultModelMaker.java:117)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ontmodels.ModelMakerOntModelCache.getModelNames(ModelMakerOntModelCache.java:48)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ontmodels.UnionModelsOntModelsCache.getModelNames(UnionModelsOntModelsCache.java:96)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ontmodels.JoinedOntModelCache.(JoinedOntModelCache.java:35)
at edu.cornell.mannlib.vitro.webapp.triplesource.impl.BasicShortTermCombinedTripleSource.createOntModelCache(BasicShortTermCombinedTripleSource.java:76)
at edu.cornell.mannlib.vitro.webapp.triplesource.impl.BasicShortTermCombinedTripleSource.(BasicShortTermCombinedTripleSource.java:62)
at edu.cornell.mannlib.vitro.webapp.triplesource.impl.BasicCombinedTripleSource.getShortTermCombinedTripleSource(BasicCombinedTripleSource.java:116)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ModelAccess$ModelAccessFactory.buildRequestModelAccess(ModelAccess.java:194)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ModelAccess.on(ModelAccess.java:158)
at edu.cornell.mannlib.vitro.webapp.controller.VitroRequest.getDisplayModel(VitroRequest.java:108)
at edu.cornell.mannlib.vitro.webapp.controller.freemarker.HomePageController.processRequest(HomePageController.java:35)
at edu.cornell.mannlib.vitro.webapp.controller.freemarker.FreemarkerHttpServlet.doGet(FreemarkerHttpServlet.java:108)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:655)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)

Logout example:
"ajp-nio-127.0.0.1-8009-exec-2" #43 daemon prio=5 os_prio=0 cpu=92412.14ms elapsed=610693.55s tid=0x00007fc1d86f1000 nid=0x34609e runnable [0x00007fbfe9cec000]
java.lang.Thread.State: RUNNABLE
at org.apache.jena.tdb.base.buffer.RecordBuffer._get(RecordBuffer.java:107)
at org.apache.jena.tdb.base.buffer.RecordBuffer.get(RecordBuffer.java:53)
at org.apache.jena.tdb.base.recordbuffer.RecordRangeIterator.hasNext(RecordRangeIterator.java:119)
at org.apache.jena.atlas.iterator.Iter$2.hasNext(Iter.java:347)
at org.apache.jena.tdb.sys.DatasetControlMRSW$IteratorCheckNotConcurrent.hasNext(DatasetControlMRSW.java:111)
at org.apache.jena.atlas.iterator.Iter$2.hasNext(Iter.java:347)
at org.apache.jena.atlas.iterator.Iter$1.hasNext(Iter.java:223)
at org.apache.jena.atlas.iterator.Iter.hasNext(Iter.java:1067)
at org.apache.jena.atlas.iterator.Iter$2.hasNext(Iter.java:347)
at org.apache.jena.util.iterator.WrappedIterator.hasNext(WrappedIterator.java:90)
at org.apache.jena.util.iterator.MapFilterIterator.hasNext(MapFilterIterator.java:54)
- locked <0x00000007fbc836c0> (a org.apache.jena.util.iterator.MapFilterIterator)
at edu.cornell.mannlib.vitro.webapp.rdfservice.impl.jena.RDFServiceJena.getGraphURIs(RDFServiceJena.java:542)
- locked <0x0000000602e4e2f8> (a java.lang.Class for edu.cornell.mannlib.vitro.webapp.rdfservice.impl.jena.RDFServiceJena)
at edu.cornell.mannlib.vitro.webapp.rdfservice.impl.jena.tdb.RDFServiceTDB.getGraphURIs(RDFServiceTDB.java:186)
at edu.cornell.mannlib.vitro.webapp.rdfservice.impl.RDFServiceFactorySingle$UnclosableRDFService.getGraphURIs(RDFServiceFactorySingle.java:130)
at edu.cornell.mannlib.vitro.webapp.rdfservice.impl.logging.LoggingRDFService.getGraphURIs(LoggingRDFService.java:145)
at edu.cornell.mannlib.vitro.webapp.dao.jena.RDFServiceModelMaker.getModelNames(RDFServiceModelMaker.java:72)
at edu.cornell.mannlib.vitro.webapp.dao.jena.RDFServiceModelMaker.listModels(RDFServiceModelMaker.java:86)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.AbstractModelMakerDecorator.listModels(AbstractModelMakerDecorator.java:98)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.AbstractModelMakerDecorator.listModels(AbstractModelMakerDecorator.java:98)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.ModelMakerWithPersistentEmptyModels.listModels(ModelMakerWithPersistentEmptyModels.java:49)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.AbstractModelMakerDecorator.listModels(AbstractModelMakerDecorator.java:98)
at edu.cornell.mannlib.vitro.webapp.modelaccess.adapters.NamedDefaultModelMaker.listModels(NamedDefaultModelMaker.java:117)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ontmodels.ModelMakerOntModelCache.getModelNames(ModelMakerOntModelCache.java:48)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ontmodels.UnionModelsOntModelsCache.getModelNames(UnionModelsOntModelsCache.java:96)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ontmodels.JoinedOntModelCache.(JoinedOntModelCache.java:35)
at edu.cornell.mannlib.vitro.webapp.triplesource.impl.BasicShortTermCombinedTripleSource.createOntModelCache(BasicShortTermCombinedTripleSource.java:76)
at edu.cornell.mannlib.vitro.webapp.triplesource.impl.BasicShortTermCombinedTripleSource.(BasicShortTermCombinedTripleSource.java:62)
at edu.cornell.mannlib.vitro.webapp.triplesource.impl.BasicCombinedTripleSource.getShortTermCombinedTripleSource(BasicCombinedTripleSource.java:116)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ModelAccess$ModelAccessFactory.buildRequestModelAccess(ModelAccess.java:194)
at edu.cornell.mannlib.vitro.webapp.modelaccess.ModelAccess.on(ModelAccess.java:158)
at edu.cornell.mannlib.vitro.webapp.controller.VitroRequest.getWebappDaoFactory(VitroRequest.java:68)
at edu.cornell.mannlib.vitro.webapp.controller.VitroRequest.getAppBean(VitroRequest.java:152)
at edu.cornell.mannlib.vitro.webapp.i18n.I18n.checkForChangeInThemeDirectory(I18n.java:216)
at edu.cornell.mannlib.vitro.webapp.i18n.I18n.getBundle(I18n.java:137)
at edu.cornell.mannlib.vitro.webapp.i18n.I18n.bundle(I18n.java:103)
at edu.cornell.mannlib.vitro.webapp.controller.edit.Logout.doPost(Logout.java:35)
at edu.cornell.mannlib.vitro.webapp.controller.edit.Logout.doGet(Logout.java:54)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:655)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)

@chenejac
Copy link
Contributor

chenejac commented Jun 8, 2023

Maybe UF sample data can be used to reproduce the issue - vivo-project/sample-data#9

@brianjlowe
Copy link
Member Author

The fact that this not a problem on all requests may be related to the graph URI cache in RDFServiceJena. The changeSetUpdate() method in RDFServiceTDB sets a dirty flag on this cache whenever a change set is written to the triple store. A change is written whenever someone logs in (not sure about logout), because we record login count and timestamp of last login.

It would initially seem that any request immediately following an update or edit should be similarly slow, not just logins.

@brianjlowe
Copy link
Member Author

It seems that we could at least make that cache invalidation a bit smarter because the change set offers easy access to the name graphs it's modifying. If there are only named graphs added, we can add them to the cache directly. Only if there is a named graph involved in a triple removal do we need to invalidate the cache, but even then it would probably be faster to test whether the graph is empty with something like "SELECT ?s ?p ?o WHERE { GRAPH ?g { ?s ?p ?o } } LIMIT 1" or even "ASK { GRAPH ?g { ?s ?p ?o } }" rather than re-listing all the graphs in the store.

@brianjlowe
Copy link
Member Author

Another option might be to rebuild the cache in the background when update activity is quiescent the way the search indexer works. I don't think there are any situations where a request will care that the graph URI list is slightly stale; in older versions of VIVO I remember freezing the graph URI list after startup and the only ill effect was that visiting the Manage Jena Models page didn't show new graphs that had appeared on ingest. Normal requests were unaffected.

It would be nice not to block incoming requests at all on these cache rebuilds.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants