Edwin Dalorzo
Aug 21, 2013, 4:52:06 PM8/21/13
to orient-...@googlegroups.com
I wrote a RESTful application consuming the services of our OrientDB 1.5.0 database using Blueprints 2.4.0.
This is a simple web application. I am not creating threads manually, neither am I using any kind of locks.
After receiving some bug reports from some users; today I decided to write an integration test for my application. I created a set of callable tasks that encapsulated a simple RESTful/HTTP request for my application. The server would end up inserting records in my OrientDB database. I put these callables in a thread pool and submitted them for execution. This would be a simulation of my client.
Interesting, my server froze. And so I went down the rabbit hole to see what was going on. Using JConsole I can see the problem is in the OrientDB client. One of its threads is frozen in TIME_WAITING and it is preventing all other threads from executing. Following a thread dump of the offending thread and one of my waiting threads as reported by JConsole.
You can see my Tomcat thread http-bio-8080-exec-15 says its waiting for a locked held by http-bio-8080-exec-16. All my other thread report the same state. Below you can see the http-bio-8080-exec-16 is TIMED_WAITING at at com.orientechnologies.orient.client.remote.OStorageRemote.beginRequest(OStorageRemote.java:1805) and it never recovers from this.
Any thoughts on what could be going on here?
2013-08-21 14:22:19
"http-bio-8080-exec-15" - Thread t@51
java.lang.Thread.State: WAITING
at sun.misc.Unsafe.park(Native Method)
- waiting to lock <e264405> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync) owned by "http-bio-8080-exec-16" t@52
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:964)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1282)
at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:731)
at com.orientechnologies.common.concur.resource.OSharedResourceAdaptive.acquireSharedLock(OSharedResourceAdaptive.java:123)
at com.orientechnologies.common.concur.resource.OSharedResourceAdaptiveExternal.acquireSharedLock(OSharedResourceAdaptiveExternal.java:40)
at com.orientechnologies.orient.core.storage.OStorageAbstract.callInLock(OStorageAbstract.java:178)
at com.orientechnologies.orient.client.remote.OStorageRemoteThread.callInLock(OStorageRemoteThread.java:437)
at com.orientechnologies.orient.core.metadata.schema.OSchemaShared.getClass(OSchemaShared.java:430)
at com.orientechnologies.orient.core.metadata.schema.OSchemaProxy.getClass(OSchemaProxy.java:145)
at com.orientechnologies.orient.core.record.ORecordSchemaAwareAbstract.setClassNameIfExists(ORecordSchemaAwareAbstract.java:111)
at com.orientechnologies.orient.core.serialization.serializer.record.string.ORecordSerializerSchemaAware2CSV.fromString(ORecordSerializerSchemaAware2CSV.java:377)
at com.orientechnologies.orient.core.serialization.serializer.record.string.ORecordSerializerStringAbstract.fromStream(ORecordSerializerStringAbstract.java:79)
at com.orientechnologies.orient.core.record.ORecordSchemaAwareAbstract.deserializeFields(ORecordSchemaAwareAbstract.java:150)
at com.orientechnologies.orient.core.record.impl.ODocument.deserializeFields(ODocument.java:1386)
at com.orientechnologies.orient.core.record.impl.ODocument.checkForFields(ODocument.java:1276)
at com.orientechnologies.orient.core.record.impl.ODocument.fieldNames(ODocument.java:492)
at com.tinkerpop.blueprints.impls.orient.OrientVertex.getEdges(OrientVertex.java:403)
at com.tinkerpop.blueprints.impls.orient.OrientVertex.getEdges(OrientVertex.java:391)
at com.tinkerpop.blueprints.util.DefaultVertexQuery$DefaultVertexQueryIterable.<init>(DefaultVertexQuery.java:110)
at com.tinkerpop.blueprints.util.DefaultVertexQuery.vertices(DefaultVertexQuery.java:84)
at com.tinkerpop.pipes.transform.VertexQueryPipe.processNextStart(VertexQueryPipe.java:113)
at com.tinkerpop.pipes.transform.VertexQueryPipe.processNextStart(VertexQueryPipe.java:19)
at com.tinkerpop.pipes.AbstractPipe.next(AbstractPipe.java:89)
at com.tinkerpop.pipes.transform.TransformFunctionPipe.processNextStart(TransformFunctionPipe.java:22)
at com.tinkerpop.pipes.AbstractPipe.next(AbstractPipe.java:89)
at com.tinkerpop.pipes.util.Pipeline.next(Pipeline.java:115)
at com.backcountry.supplychain.graph.data.repository.readers.AttributeValueReader.read(AttributeValueReader.java:32)
at com.backcountry.supplychain.graph.data.repository.readers.AttributeValueReader.read(AttributeValueReader.java:21)
at com.backcountry.supplychain.graph.data.repository.readers.BaseEntityReader.read(BaseEntityReader.java:40)
at com.backcountry.supplychain.graph.data.repository.UnitOfWork.map(UnitOfWork.java:187)
at com.backcountry.supplychain.graph.data.repository.tasks.GetCompatibleAttributesBySkuId$1.compute(GetCompatibleAttributesBySkuId.java:43)
at com.backcountry.supplychain.graph.data.repository.tasks.GetCompatibleAttributesBySkuId$1.compute(GetCompatibleAttributesBySkuId.java:40)
at com.tinkerpop.pipes.transform.TransformFunctionPipe.processNextStart(TransformFunctionPipe.java:22)
at com.tinkerpop.pipes.AbstractPipe.next(AbstractPipe.java:89)
at com.tinkerpop.pipes.util.Pipeline.next(Pipeline.java:115)
at com.tinkerpop.pipes.util.PipeHelper.fillCollection(PipeHelper.java:52)
at com.tinkerpop.gremlin.java.GremlinPipeline.fill(GremlinPipeline.java:1575)
at com.backcountry.supplychain.graph.data.repository.tasks.GetCompatibleAttributesBySkuId.execute(GetCompatibleAttributesBySkuId.java:39)
at com.backcountry.supplychain.graph.data.repository.tasks.GetCompatibleAttributesBySkuId.execute(GetCompatibleAttributesBySkuId.java:22)
at com.backcountry.supplychain.graph.data.repository.GraphRequestExecutor.attemptRequest(GraphRequestExecutor.java:80)
at com.backcountry.supplychain.graph.data.repository.GraphRequestExecutor.execute(GraphRequestExecutor.java:61)
at com.backcountry.supplychain.graph.data.repository.readers.BaseEntityReader$LazyLoadingSet.delegate(BaseEntityReader.java:94)
at com.backcountry.supplychain.graph.data.repository.readers.BaseEntityReader$LazyLoadingSet.delegate(BaseEntityReader.java:78)
at com.google.common.collect.ForwardingCollection.iterator(ForwardingCollection.java:60)
at com.backcountry.supplychain.graph.data.model.Sku.getCompatibleAttributeById(Sku.java:69)
at com.backcountry.supplychain.graph.business.service.DefaultSkuService.addCompatibleAttribute(DefaultSkuService.java:153)
at com.backcountry.supplychain.graph.ws.controller.SkuController.postCompatibleAttribute(SkuController.java:233)
at sun.reflect.GeneratedMethodAccessor62.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:219)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:746)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:687)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:915)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:822)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:796)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1023)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310)
- locked <5bf831cc> (a org.apache.tomcat.util.net.SocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:724)
Locked ownable synchronizers:
- locked <5a0f8c33> (a java.util.concurrent.ThreadPoolExecutor$Worker)
"http-bio-8080-exec-16" - Thread t@52
java.lang.Thread.State: TIMED_WAITING
at java.lang.Object.wait(Native Method)
- waiting on <5016882a> (a java.util.ArrayList)
at com.orientechnologies.orient.client.remote.OStorageRemote.beginRequest(OStorageRemote.java:1805)
at com.orientechnologies.orient.client.remote.OStorageRemote.openRemoteDatabase(OStorageRemote.java:1552)
at com.orientechnologies.orient.client.remote.OStorageRemote.open(OStorageRemote.java:176)
at com.orientechnologies.orient.client.remote.OStorageRemoteThread.open(OStorageRemoteThread.java:70)
at com.orientechnologies.orient.core.db.raw.ODatabaseRaw.open(ODatabaseRaw.java:89)
at com.orientechnologies.orient.core.db.ODatabaseWrapperAbstract.open(ODatabaseWrapperAbstract.java:49)
at com.orientechnologies.orient.core.db.record.ODatabaseRecordAbstract.open(ODatabaseRecordAbstract.java:119)
at com.orientechnologies.orient.core.db.ODatabaseWrapperAbstract.open(ODatabaseWrapperAbstract.java:49)
at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.openOrCreate(OrientBaseGraph.java:759)
- locked <41cde0a7> (a com.tinkerpop.blueprints.impls.orient.OrientGraph)
at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.<init>(OrientBaseGraph.java:98)
at com.tinkerpop.blueprints.impls.orient.OrientTransactionalGraph.<init>(OrientTransactionalGraph.java:34)
at com.tinkerpop.blueprints.impls.orient.OrientGraph.<init>(OrientGraph.java:32)
at com.backcountry.supplychain.graph.data.repository.orientdb.OrientDbGraphConnectionFactory.open(OrientDbGraphConnectionFactory.java:42)
at com.backcountry.supplychain.graph.data.repository.GraphRequestExecutor$1.initialValue(GraphRequestExecutor.java:36)
at com.backcountry.supplychain.graph.data.repository.GraphRequestExecutor$1.initialValue(GraphRequestExecutor.java:33)
at java.lang.ThreadLocal.setInitialValue(ThreadLocal.java:160)
at java.lang.ThreadLocal.get(ThreadLocal.java:150)
at com.backcountry.supplychain.graph.data.repository.GraphRequestExecutor.attemptRequest(GraphRequestExecutor.java:77)
at com.backcountry.supplychain.graph.data.repository.GraphRequestExecutor.execute(GraphRequestExecutor.java:61)
at com.backcountry.supplychain.graph.data.repository.BaseGraphRepository.processRequest(BaseGraphRepository.java:17)
at com.backcountry.supplychain.graph.data.repository.DefaultSkuRepository.save(DefaultSkuRepository.java:58)
at com.backcountry.supplychain.graph.business.service.DefaultSkuService.save(DefaultSkuService.java:51)
at com.backcountry.supplychain.graph.business.service.DefaultSkuService.addCompatibleAttribute(DefaultSkuService.java:159)
at com.backcountry.supplychain.graph.ws.controller.SkuController.postCompatibleAttribute(SkuController.java:233)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:219)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:746)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:687)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:915)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:822)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:796)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1023)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310)
- locked <335815b1> (a org.apache.tomcat.util.net.SocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:724)
Locked ownable synchronizers:
- locked <3ce13700> (a java.util.concurrent.ThreadPoolExecutor$Worker)
- locked <e264405> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
Edwin Dalorzo
Aug 21, 2013, 5:00:17 PM8/21/13
to orient-...@googlegroups.com
This is my configuration dump, in case it helps:
OrientDB 1.5.0 configuration dump:
- ENVIRONMENT
+ environment.dumpCfgAtStartup = false
+ environment.concurrent = true
- MEMORY
+ memory.optimizeThreshold = 0.7
- JVM
+ jvm.gc.delayForOptimize = 600
- STORAGE
+ storage.diskCache.bufferSize = 2048
+ storage.compressionMethod = snappy
+ storage.useWAL = true
+ storage.wal.cacheSize = 3000
+ storage.wal.maxSegmentSize = 51200
+ storage.wal.maxSize = 153600
+ storage.wal.commitTimeout = 1000
+ storage.wal.shutdownTimeout = 10000
+ storage.wal.fuzzyCheckpointInterval = 2592000
+ storage.wal.fuzzyCheckpointShutdownWait = 600
+ storage.wal.fullCheckpointShutdownTimeout = 600
+ storage.wal.path = null
+ storage.makeFullCheckpointAfterCreate = true
+ storage.makeFullCheckpointAfterClusterCreate = true
+ storage.diskCache.pageSize = 64
+ storage.diskCache.writeQueueLength = 15000
+ storage.diskPageCache.lockTimeOut = 1000
+ storage.lowestFreeListBound = 16
+ storage.cluster.useNodeIdAsClusterPosition = false
+ storage.keepOpen = true
+ storage.lockTimeout = 600000
+ storage.record.lockTimeout = 5000
+ storage.useTombstones = false
- CACHE
+ cache.level1.enabled = true
+ cache.level1.size = 1000
+ cache.level2.enabled = true
+ cache.level2.size = 10000
+ cache.level2.impl = com.orientechnologies.orient.core.cache.ODefaultCache
+ cache.level2.strategy = 0
- OBJECT
+ object.saveOnlyDirty = false
- DB
+ db.pool.min = 1
+ db.pool.max = 20
+ db.mvcc = true
+ db.mvcc.throwfast = false
+ db.validation = true
+ db.use.distributedVersion = false
- NONTX
+ nonTX.recordUpdate.synch = false
+ nonTX.clusters.sync.immediately = manindex
- TX
+ tx.useLog = true
+ tx.autoRetry = 10
+ tx.log.fileType = classic
+ tx.log.synch = false
+ tx.commit.synch = false
- BLUEPRINTS
+ blueprints.graph.txMode = 0
- HASHTABLE
+ hashTable.slitBucketsBuffer.length = 1500
- INDEX
+ index.auto.rebuildAfterNotSoftClose = true
+ index.auto.lazyUpdates = 10000
+ index.manual.lazyUpdates = 1
- MVRBTREE
+ mvrbtree.timeout = 5000
+ mvrbtree.nodePageSize = 256
+ mvrbtree.loadFactor = 0.7
+ mvrbtree.optimizeThreshold = 100000
+ mvrbtree.entryPoints = 64
+ mvrbtree.optimizeEntryPointsFactor = 1.0
+ mvrbtree.entryKeysInMemory = false
+ mvrbtree.entryValuesInMemory = false
+ mvrbtree.ridBinaryThreshold = 8
+ mvrbtree.ridNodePageSize = 64
+ mvrbtree.ridNodeSaveMemory = false
- LAZYSET
+ lazyset.workOnStream = true
- FILE
+ file.lock = true
+ file.defrag.strategy = 0
+ file.defrag.holeMaxDistance = 32768
+ file.mmap.useOldManager = false
+ file.mmap.autoFlush.timer = 30
+ file.mmap.autoFlush.unusedTime = 30
+ file.mmap.lockMemory = true
+ file.mmap.strategy = 0
+ file.mmap.blockSize = 1048576
+ file.mmap.bufferSize = 8192
+ file.mmap.maxMemory = 3707965440
+ file.mmap.overlapStrategy = 2
+ file.mmap.forceDelay = 10
+ file.mmap.forceRetry = 50
- JNA
+ jna.disable.system.library = true
- FILE
+ file.cluster.useLHPEPS = false
+ file.cluster.useMemoryLHCluster = false
- NETWORK
+ network.maxConcurrentSessions = 1000
+ network.socketBufferSize = 32768
+ network.lockTimeout = 15000
+ network.socketTimeout = 15000
+ network.retry = 5
+ network.retryDelay = 500
+ network.binary.loadBalancing.enabled = false
+ network.binary.loadBalancing.timeout = 2000
+ network.binary.maxLength = 32736
+ network.binary.readResponse.maxTimes = 20
+ network.binary.debug = false
+ network.http.maxLength = 1000000
+ network.http.charset = utf-8
+ network.http.sessionExpireTimeout = 300
- PROFILER
+ profiler.enabled = false
+ profiler.config = null
+ profiler.autoDump.interval = 0
+ profiler.autoDump.reset = true
- LOG
+ log.console.level = info
+ log.file.level = fine
- COMMAND
+ command.timeout = 0
- CLIENT
+ client.channel.minPool = 1
+ client.channel.maxPool = 20
+ client.connectionPool.waitTimeout = 5000
+ client.channel.dbReleaseWaitTimeout = 10000
- SERVER
+ server.channel.cleanDelay = 5000
+ server.cache.staticFile = false
+ server.cache.2q.increaseOnDemand = true
+ server.cache.2q.increaseStep = 0.1
+ server.log.dumpClientExceptionLevel = FINE
+ server.log.dumpClientExceptionFullStackTrace = true
Edwin Dalorzo
Aug 27, 2013, 11:14:36 AM8/27/13
to orient-...@googlegroups.com
I created an issue for this case where I document the case:
Reply all
Reply to author
Forward
0 new messages