Hello,
I really hope someone can shed some light on the performance issues that we have been experiencing. Thank you much in advance.
Regards,
-Chris
I have attached 2 html files - one is heap dump of OrientDB server and the other is App 2 VM.
Below is also partial stack trace of App 2 and some code snippet where main transaction boundaries are.
We are getting long commit time and eventually runs out of memory, currently Orient is becoming unusable for what we are trying to do with client App 2 as described below.
Background:
Database Server instance using Java 8
1) We run OrientDB using server.sh/bat as a standalone and with 1G of heap space and default Disk Cache
Databases
2) We have 2 databases created as plocal and graph, let's name them, Expansion & Universe.
3) 2 have 2 client applications, both are spring boot project with an embedded jetty container, run as executable jars
Java Client Applications - Spring Boot using Java 8
4) App 1 - reads a large xml file (670 Meg and process each business unit of at a time) and create Vertices and Edges based on the
business concepts described in the xml. NOTE, in both app we define the schema for Vertices and Edge Type definitions.
For APP 1, Expansion DB barely has any index as we mostly write blindly as an expansion of elements from XML. BUT, we will need to read the data
from APP 2. To load the file and expand the xml int vertex and edge representation it takes anywhere from 55 to 2 hours, depending on SSD vs regular disk, this is on a brand new clean DB.
One thing that is clear, as data grows, same data file loaded again will take longer to load, seems like linear growth. I noticed something in the forum about this already.
This file has about 35,000 business unit worth of data. The raw size in DB is 2,610,075 edges, 2,610,076 vertices. We have defined about 16 Vertices (vertex types) and 23 Edges (edge types) in Expansion and Universe DB.
This is just one file and we will get incremental update everyday and will grow over the time. So, we would need to be able to handle large amount of data in MANY millions in both databases.
App 1 runs fine with 256Meg of heap space and though it gets slower over the time, it runs.
5) App 2 - All edge types have non unique index as we need to look for existing of vertices in an edge as well as we keep history of relationships as in what point a relationship is no longer current.
We also have index for some of the Vertex where we have some business key we need to query on. Overall # of indices are certainly much more than Expansion DB,
but not overwhelming as we would be doing lot of bulk writing (create/update vertices, create/update edges) as well as reading to look for existing vertices or edges.
6) NOTE, we use connection pool and transaction. Our transaction boundary would process a Business unit worth of data, which translates into average of 100 vertices/edges.
However some extreme cases we could end up creating/updating about 1500 vertices/edges.
7) App 2 has 2 Graph connection Factory one for each DB (Expansion and Universe). App reads one Business unit worth of vertices/edges from Expansion DB and in a transaction writes (create/update/lookup) into Universe DB.
Average for this varies from 2 sec to 4 secs depending on SSD vs non-SSD disks.
8) With 1G of heap for the App2, it will eventually get out of memory exception. I have only been able to process 30,000 business units read from Expansion DB and it took over 11 hours before getting out of memory.
This is on a SSD drive. At this performance, the app and DB becomes pretty much unusable.
9) Tried few suggestions based on forum and documentation - disabling transaction log, but I don't think it made any real difference.
Here's the stack trace from App 2. I have also heap dumps from both OrientDB server and App 2.
Would love some insights as to what the options are. I am curious if anyone else is using OrientDB for something like the way I described. I don't think this usecase is anything out of the ordinary.
--- Stack Trace from Client App 2: Note, Caused by: java.lang.OutOfMemoryError: Java heap space---
2015-09-11 04:11:16.858 DEBUG 1132 --- [qtp174969681-23] .b.u.u.UniverseMergeRequestServiceFacade : Processed 30555 statements with an average of 1332 milliseconds
2015-09-11 04:17:52.406 DEBUG 1132 --- [qtp174969681-23] c.b.u.u.StatementUniverseMergeService : {"delivery-id":"1e556f40-7e00-d9ba-9464-22000b9447eb","log-type":"universe-merge-statement","universe-merge-request-uuid":"c0fbbf7d-358e-4a01-a5c1-44007a311aab","statement-uid":"1e4ed31a-3631-df77-b997-22000a4590b6"}
2015-09-11 04:17:55.268 DEBUG 1132 --- [qtp174969681-23] c.b.u.u.StatementUniverseMergeService : {"delivery-id":"1e556f40-7e00-d9ba-9464-22000b9447eb","log-type":"universe-merge-statement","universe-merge-request-uuid":"c0fbbf7d-358e-4a01-a5c1-44007a311aab","statement-uid":"1e4ed31a-3f9b-d96a-b997-22000a4590b6"}
2015-09-11 04:18:01.435 DEBUG 1132 --- [qtp174969681-23] c.b.u.u.StatementUniverseMergeService : {"delivery-id":"1e556f40-7e00-d9ba-9464-22000b9447eb","log-type":"universe-merge-statement","universe-merge-request-uuid":"c0fbbf7d-358e-4a01-a5c1-44007a311aab","statement-uid":"1e4ed31a-3fe7-d518-b997-22000a4590b6"}
2015-09-11 04:34:02.328 ERROR 1132 --- [qtp174969681-23] .b.u.u.UniverseMergeRequestServiceFacade : Universe merge request for deliveries failed for extraction date > 2001-01-01 00:00:00.0
com.bps.commons.exception.StateDumpException: Exception thrown when creating the statement due to Exception during response processing.
at com.bps.urjanet.universe.StatementUniverseMergeService.merge(StatementUniverseMergeService.java:97)
at com.bps.urjanet.universe.UniverseMergeRequestServiceFacade.processMergeRequest(UniverseMergeRequestServiceFacade.java:87)
at com.bps.urjanet.universe.resource.UniverseMergeResource.requestUniverseMerge(UniverseMergeResource.java:47)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:151)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:172)
at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:152)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:104)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:384)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:342)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:101)
at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:271)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:297)
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:254)
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1030)
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:377)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:381)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:344)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:221)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)
at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:224)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.springframework.boot.actuate.autoconfigure.EndpointWebMvcAutoConfiguration$ApplicationContextHeaderFilter.doFilterInternal(EndpointWebMvcAutoConfiguration.java:291)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:102)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:154)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:201)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:110)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:57)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:50)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:85)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
at org.springframework.boot.actuate.autoconfigure.MetricFilterAutoConfiguration$MetricsFilter.doFilterInternal(MetricFilterAutoConfiguration.java:90)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
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.HandlerWrapper.handle(HandlerWrapper.java:97)
at org.eclipse.jetty.server.Server.handle(Server.java:497)
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(Unknown Source)
Caused by: com.orientechnologies.orient.enterprise.channel.binary.OResponseProcessingException: Exception during response processing.
at com.orientechnologies.orient.enterprise.channel.binary.OChannelBinaryAsynchClient.throwSerializedException(OChannelBinaryAsynchClient.java:445)
at com.orientechnologies.orient.enterprise.channel.binary.OChannelBinaryAsynchClient.handleStatus(OChannelBinaryAsynchClient.java:400)
at com.orientechnologies.orient.enterprise.channel.binary.OChannelBinaryAsynchClient.beginResponse(OChannelBinaryAsynchClient.java:282)
at com.orientechnologies.orient.enterprise.channel.binary.OChannelBinaryAsynchClient.beginResponse(OChannelBinaryAsynchClient.java:171)
at com.orientechnologies.orient.client.remote.OStorageRemote.beginResponse(OStorageRemote.java:2136)
at com.orientechnologies.orient.client.remote.OStorageRemote.commit(OStorageRemote.java:1364)
at com.orientechnologies.orient.client.remote.OStorageRemoteThread.commit(OStorageRemoteThread.java:448)
at com.orientechnologies.orient.core.tx.OTransactionOptimistic.doCommit(OTransactionOptimistic.java:596)
at com.orientechnologies.orient.core.tx.OTransactionOptimistic.commit(OTransactionOptimistic.java:156)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:2578)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.commit(ODatabaseDocumentTx.java:2547)
at com.tinkerpop.blueprints.impls.orient.OrientTransactionalGraph.commit(OrientTransactionalGraph.java:161)
at com.bps.urjanet.universe.StatementUniverseMergeService.merge(StatementUniverseMergeService.java:85)
... 95 common frames omitted
Caused by: java.lang.OutOfMemoryError: Java heap space
2015-09-11 04:34:02.349 ERROR 1132 --- [qtp174969681-23] c.b.u.u.r.StateDumpExceptionMapper : StateDumpExceptionMapper>>toResponse:Error Occured: Exception thrown when updating the StatementsDelivery due to Transaction was rolled back more times than it was started.
Transaction was rolled back more times than it was started.
com.bps.commons.exception.StateDumpException: Exception thrown when updating the StatementsDelivery due to Transaction was rolled back more times than it was started.
...
Caused by: com.orientechnologies.orient.core.exception.OTransactionException: Transaction was rolled back more times than it was started.
at com.orientechnologies.orient.core.tx.OTransactionOptimistic.rollback(OTransactionOptimistic.java:188)
at com.orientechnologies.orient.core.tx.OTransactionOptimistic.rollback(OTransactionOptimistic.java:169)
at com.orientechnologies.orient.server.network.protocol.binary.ONetworkProtocolBinary.endResponse(ONetworkProtocolBinary.java:1764)
at com.orientechnologies.orient.server.network.protocol.binary.ONetworkProtocolBinary.readRecord(ONetworkProtocolBinary.java:1662)
at com.orientechnologies.orient.server.network.protocol.binary.ONetworkProtocolBinary.executeRequest(ONetworkProtocolBinary.java:353)
at com.orientechnologies.orient.server.network.protocol.binary.OBinaryNetworkProtocolAbstract.execute(OBinaryNetworkProtocolAbstract.java:223)
at com.orientechnologies.common.thread.OSoftThread.run(OSoftThread.java:77)
///
Code snippet of where the main transaction processing happens. This method is called from another service to loop for each Business unit of work.
As you can see, each business unit of work is where transactions are happening.
public TreeVertex merge(params...){
List<Reference> references = new ArrayList<>();
List<MeasurementPeriod> measurementPeriods = new ArrayList<>();
List<SummaryData> summaryDatas = new ArrayList<>();
List<RateComponents> rateComponentsList = new ArrayList<>();
Map<String, OrientVertex> vertexMap = new HashMap<>(); //<UID, Vertex> Only objects that have a UID that are created in process.
OrientGraph mergedGraph = this.orientUniverseGraphFactory.getTx(); //Exception should flow through. This is a problem.
OrientVertex statement = null;
try {
mergedGraph.begin();
mergedGraph.getRawGraph().getTransaction().setUsingLog(false);
statementProcessor.endEdgesWithStatementUid(mergedGraph, uid); //If any edges are found with the statement UID, then end those relationships.
statement = process(mergedGraph, expandedTreeVertex, deliveryId, uid, vertexMap,
references, measurementPeriods, summaryDatas, rateComponentsList
);
mergedGraph.commit();
} catch (Exception e) {
mergedGraph.rollback();
throw new StateDumpException("Exception thrown when creating the statement due to " + e.getMessage(), e)
.addStateDump("universeMergeRequestUuid", universeMergeRequestUuid)
.addStateDump("deliveryId", deliveryId)
.addStateDump("statement-uid", uid);
} finally {
if (mergedGraph != null) {
mergedGraph.shutdown();
}
}
mergedGraph = this.orientUniverseGraphFactory.getTx(); //Exception should flow through. This is a problem.
try {
mergedGraph.begin();
mergedGraph.getRawGraph().getTransaction().setUsingLog(false);
childProcessor.postProcess(mergedGraph, statement, references, measurementPeriods, summaryDatas, rateComponentsList);
mergedGraph.commit();
} catch (Exception e) {
mergedGraph.rollback();
throw new StateDumpException("Exception thrown when creating the statement due to " + e.getMessage(), e)
.addStateDump("universeMergeRequestUuid", universeMergeRequestUuid)
.addStateDump("deliveryId", deliveryId)
.addStateDump("uid", uid);
} finally {
if (mergedGraph != null) {
mergedGraph.shutdown();
}
}
}
----