On Feb 18, 2010, at 7:52 AM, Kevan Miller wrote:
On Feb 18, 2010, at 3:16 AM, David Blevins wrote:
Hacked up a new chunk of pooling code for Stateless beans that
allows the pool to shrink down at some point after the max is hit.
It also allows for a minimum to be set. The mix is achieved via a
combination of hard references and SoftReference objects.
The tests for the pool itself and the
StatelessInstanceManagerPoolingTest work fine, but for some reason
when all tests are running together things eventually lockup. I've
tried to 'kill -QUIT' the test process to see where it's locked,
but for some reason I can't seem to find where the output is going,
it's not in the surefire output. Not sure there is some maven
option I need to set.
Looking for some help in finding the issue. I've attached a patch
to this JIRA:
http://issues.apache.org/jira/browse/OPENEJB-1235
Any tips welcome.
I had some issues with 'kill -QUIT' not working on my Mac a while
ago. Don't think I ever figured out why. But seems to be working for
me at the moment... JVM sends the output to STDOUT. Don't know what
maven/surefire may be doing with that.
Given the nature of your changes and the fact that individual tests
work ok, I think we can assume we're hitting an OOME and you can't
find kill -QUIT output because nothing's being generated.
For OOME's, I use the following in my .mavenrc file:
MAVEN_OPTS="-Xmx1024m -Xms512m -XX:MaxPermSize=512m -XX:
+HeapDumpOnOutOfMemoryError"
That will cause a heapdump to be created on any OOME. I usually
forget the file name that's generated. So, end up running something
like 'java -Xmx4k -XX:+HeapDumpOnOutOfMemoryError SomeClass' to
generate a sample (and I now see that on a Mac it looks like:
java_pid51424.hprof).
Those settings won't affect the Surefire process. So, you need to
set -XX:+HeapDumpOnOutOfMemoryError in the pom.xml, for your
Surefire process.
If you can remind me how to run the tests, I can take a look at
this...
Started running into this again and with a little help from Brett
Porter managed to get some heap dumps. I added the following flag and
it redirects the output to a file which seems to be enough to get the
heap dumps to show up somewhere:
mvn clean install -Dmaven.test.redirectTestOutputToFile=true
There's a buffer flushing issue in their "redirect" code, so you have
to dump twice to build up enough bytes to flush the first dump
completely.
Anyway, here's the output. I see a few "locked" items, but it isn't
clear where the source is.
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
- - - - - - - - - - - - - - - - - - - - -
( as a gist paste in case it wraps badly http://gist.github.com/311954 )
Full thread dump Java HotSpot(TM) Client VM (1.5.0_20-141 mixed mode):
"BrokerService" daemon prio=5 tid=0x0101f380 nid=0x954a00 waiting for
monitor entry [0xb1011000..0xb1011d90]
at java.util.concurrent.SynchronousQueue
$LifoWaitQueue.enq(SynchronousQueue.java:162)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:
437)
at
java
.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:475)
at java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:613)
"VMTransport" daemon prio=5 tid=0x01027010 nid=0x9d9600 waiting for
monitor entry [0xb0f8f000..0xb0f90d90]
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:242)
at
org.apache.openejb.core.TempClassLoader.loadClass(TempClassLoader.java:
92)
- locked <0x07f2a298> (a org.apache.openejb.core.TempClassLoader)
at
org.apache.openejb.core.TempClassLoader.loadClass(TempClassLoader.java:
66)
at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:374)
- locked <0x07f2a298> (a org.apache.openejb.core.TempClassLoader)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:242)
at
org
.apache
.openjpa
.enhance
.PCClassFileTransformer.needsEnhance(PCClassFileTransformer.java:186)
at
org
.apache
.openjpa
.enhance.PCClassFileTransformer.transform0(PCClassFileTransformer.java:
132)
at
org
.apache
.openjpa
.enhance.PCClassFileTransformer.transform(PCClassFileTransformer.java:
120)
at org.apache.openjpa.persistence.PersistenceProviderImpl
$ClassTransformerImpl.transform(PersistenceProviderImpl.java:210)
at org.apache.openejb.persistence.PersistenceUnitInfoImpl
$
PersistenceClassFileTransformer.transform(PersistenceUnitInfoImpl.java:
303)
at
sun.instrument.TransformerManager.transform(TransformerManager.java:122)
at
sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:
155)
at java.util.concurrent.SynchronousQueue
$LifoWaitQueue.enq(SynchronousQueue.java:162)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:
437)
at
java
.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:475)
at java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:613)
"Thread-1" daemon prio=5 tid=0x01025680 nid=0x994000 waiting on
condition [0xb0e8e000..0xb0e8ed90]
at java.lang.Thread.sleep(Native Method)
at org.apache.geronimo.transaction.manager.TransactionTimer
$CurrentTime.run(TransactionTimer.java:38)
"Timer-0" daemon prio=5 tid=0x01020650 nid=0x94a000 in Object.wait()
[0xb0e0d000..0xb0e0dd90]
at java.lang.Object.wait(Native Method)
- waiting on <0x07edb558> (a java.util.TaskQueue)
at java.util.TimerThread.mainLoop(Timer.java:509)
- locked <0x07edb558> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:462)
"ActiveMQ Transport Server: tcp://localhost:61616" daemon prio=9
tid=0x0101f710 nid=0x942400 runnable [0xb0d8c000..0xb0d8cd90]
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0x07eca320> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:450)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at
org
.apache
.activemq.transport.tcp.TcpTransportServer.run(TcpTransportServer.java:
280)
at java.lang.Thread.run(Thread.java:613)
"ActiveMQ Transport Server Thread Handler: tcp://localhost:61616"
daemon prio=8 tid=0x0101ace0 nid=0x94b000 waiting on condition
[0xb0d0b000..0xb0d0bd90]
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:
146)
at java.util.concurrent.locks.AbstractQueuedSynchronizer
$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1879)
at
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:
396)
at org.apache.activemq.transport.tcp.TcpTransportServer
$1.run(TcpTransportServer.java:352)
at java.lang.Thread.run(Thread.java:613)
"Low Memory Detector" daemon prio=5 tid=0x01009ff0 nid=0x86ec00
runnable [0x00000000..0x00000000]
"CompilerThread0" daemon prio=9 tid=0x010095e0 nid=0x86d200 waiting on
condition [0x00000000..0xb0b077d8]
"Signal Dispatcher" daemon prio=9 tid=0x01009150 nid=0x86c400 waiting
on condition [0x00000000..0x00000000]
"Finalizer" daemon prio=8 tid=0x01007a30 nid=0x818800 in Object.wait()
[0xb0a05000..0xb0a05d90]
at java.lang.Object.wait(Native Method)
- waiting on <0x07d118f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
- locked <0x07d118f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=10 tid=0x01007790 nid=0x817a00 in
Object.wait() [0xb0984000..0xb0984d90]
at java.lang.Object.wait(Native Method)
- waiting on <0x07d11980> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x07d11980> (a java.lang.ref.Reference$Lock)
"main" prio=5 tid=0x01001890 nid=0xb0801000 waiting for monitor entry
[0xb07fe000..0xb0800188]
at java.lang.ClassLoader.findBootstrapClass(Native Method)
at java.lang.ClassLoader.findBootstrapClass0(ClassLoader.java:946)
at java.lang.ClassLoader.loadClass(ClassLoader.java:308)
- locked <0x07d14028> (a sun.misc.Launcher$ExtClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
- locked <0x07d11e58> (a sun.misc.Launcher$AppClassLoader)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:280)
- locked <0x07d11e58> (a sun.misc.Launcher$AppClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:374)
- locked <0x07d11e58> (a sun.misc.Launcher$AppClassLoader)
at
org.apache.activemq.ActiveMQConnection.<init>(ActiveMQConnection.java:
186)
at
org
.apache
.activemq
.ActiveMQConnectionFactory
.createActiveMQConnection(ActiveMQConnectionFactory.java:288)
at
org
.apache
.activemq
.ActiveMQConnectionFactory
.createActiveMQConnection(ActiveMQConnectionFactory.java:256)
at
org
.apache
.activemq
.ActiveMQConnectionFactory
.createConnection(ActiveMQConnectionFactory.java:182)
at
org
.apache
.activemq
.ra
.ActiveMQConnectionSupport
.makeConnection(ActiveMQConnectionSupport.java:79)
at
org
.apache
.activemq
.ra
.ActiveMQConnectionSupport
.makeConnection(ActiveMQConnectionSupport.java:61)
at
org
.apache
.activemq
.ra
.ActiveMQManagedConnectionFactory
.createManagedConnection(ActiveMQManagedConnectionFactory.java:169)
at
org
.apache
.geronimo
.connector
.outbound
.MCFConnectionInterceptor.getConnection(MCFConnectionInterceptor.java:
48)
at
org
.apache
.geronimo
.connector
.outbound
.XAResourceInsertionInterceptor
.getConnection(XAResourceInsertionInterceptor.java:41)
at
org
.apache
.geronimo
.connector
.outbound
.SinglePoolConnectionInterceptor
.internalGetConnection(SinglePoolConnectionInterceptor.java:67)
- locked <0x07ede778> (a
org.apache.geronimo.connector.outbound.SinglePoolConnectionInterceptor
$PoolDeque)
at
org
.apache
.geronimo
.connector
.outbound
.AbstractSinglePoolConnectionInterceptor
.getConnection(AbstractSinglePoolConnectionInterceptor.java:78)
at
org
.apache
.geronimo
.connector
.outbound
.TransactionEnlistingInterceptor
.getConnection(TransactionEnlistingInterceptor.java:46)
at
org
.apache
.geronimo
.connector
.outbound
.TransactionCachingInterceptor
.getConnection(TransactionCachingInterceptor.java:94)
at
org
.apache
.geronimo
.connector
.outbound
.ConnectionHandleInterceptor
.getConnection(ConnectionHandleInterceptor.java:43)
at
org
.apache
.geronimo
.connector.outbound.TCCLInterceptor.getConnection(TCCLInterceptor.java:
39)
at
org
.apache
.geronimo
.connector
.outbound
.ConnectionTrackingInterceptor
.getConnection(ConnectionTrackingInterceptor.java:66)
at
org
.apache
.geronimo
.connector
.outbound
.AbstractConnectionManager
.allocateConnection(AbstractConnectionManager.java:87)
at
org
.apache
.activemq
.ra
.ActiveMQConnectionFactory
.createConnection(ActiveMQConnectionFactory.java:94)
at
org
.apache
.activemq
.ra
.ActiveMQConnectionFactory
.createConnection(ActiveMQConnectionFactory.java:67)
at
org
.apache.openejb.config.LocalClientTest.assertRefs(LocalClientTest.java:
140)
at
org.apache.openejb.config.LocalClientTest.test(LocalClientTest.java:118)
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:592)
at junit.framework.TestCase.runTest(TestCase.java:168)
at junit.framework.TestCase.runBare(TestCase.java:134)
at junit.framework.TestResult$1.protect(TestResult.java:110)
at junit.framework.TestResult.runProtected(TestResult.java:128)
at junit.framework.TestResult.run(TestResult.java:113)
at junit.framework.TestCase.run(TestCase.java:124)
at junit.framework.TestSuite.runTest(TestSuite.java:232)
at junit.framework.TestSuite.run(TestSuite.java:227)
at
org
.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:
79)
at
org
.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:
62)
at
org
.apache
.maven
.surefire
.suite
.AbstractDirectoryTestSuite
.executeTestSet(AbstractDirectoryTestSuite.java:140)
at
org
.apache
.maven
.surefire
.suite
.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:165)
at org.apache.maven.surefire.Surefire.run(Surefire.java:107)
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:592)
at
org
.apache
.maven
.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:
289)
at
org
.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:
993)
"VM Thread" prio=9 tid=0x01006ef0 nid=0x801800 runnable
"VM Periodic Task Thread" prio=9 tid=0x0100ac70 nid=0x86fa00 waiting
on condition
"Exception Catcher Thread" prio=10 tid=0x01001ab0 nid=0x80a000 runnable
Found one Java-level deadlock:
=============================
"VMTransport":
waiting to lock monitor 0x00819694 (object 0x07d11e58, a
sun.misc.Launcher$AppClassLoader),
which is held by "main"
"main":
waiting to lock monitor 0x008196b8 (object 0x255a4b40, a [[I),
which is held by "VMTransport"
Java stack information for the threads listed above:
===================================================
"VMTransport":
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:242)
at
org.apache.openejb.core.TempClassLoader.loadClass(TempClassLoader.java:
92)
- locked <0x07f2a298> (a org.apache.openejb.core.TempClassLoader)
at
org.apache.openejb.core.TempClassLoader.loadClass(TempClassLoader.java:
66)
at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:374)
- locked <0x07f2a298> (a org.apache.openejb.core.TempClassLoader)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:242)
at
org
.apache
.openjpa
.enhance
.PCClassFileTransformer.needsEnhance(PCClassFileTransformer.java:186)
at
org
.apache
.openjpa
.enhance.PCClassFileTransformer.transform0(PCClassFileTransformer.java:
132)
at
org
.apache
.openjpa
.enhance.PCClassFileTransformer.transform(PCClassFileTransformer.java:
120)
at org.apache.openjpa.persistence.PersistenceProviderImpl
$ClassTransformerImpl.transform(PersistenceProviderImpl.java:210)
at org.apache.openejb.persistence.PersistenceUnitInfoImpl
$
PersistenceClassFileTransformer.transform(PersistenceUnitInfoImpl.java:
303)
at
sun.instrument.TransformerManager.transform(TransformerManager.java:122)
at
sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:
155)
at java.util.concurrent.SynchronousQueue
$LifoWaitQueue.enq(SynchronousQueue.java:162)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:
437)
at
java
.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:475)
at java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:613)
"main":
at java.lang.ClassLoader.findBootstrapClass(Native Method)
at java.lang.ClassLoader.findBootstrapClass0(ClassLoader.java:946)
at java.lang.ClassLoader.loadClass(ClassLoader.java:308)
- locked <0x07d14028> (a sun.misc.Launcher$ExtClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
- locked <0x07d11e58> (a sun.misc.Launcher$AppClassLoader)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:280)
- locked <0x07d11e58> (a sun.misc.Launcher$AppClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:374)
- locked <0x07d11e58> (a sun.misc.Launcher$AppClassLoader)
at
org.apache.activemq.ActiveMQConnection.<init>(ActiveMQConnection.java:
186)
at
org
.apache
.activemq
.ActiveMQConnectionFactory
.createActiveMQConnection(ActiveMQConnectionFactory.java:288)
at
org
.apache
.activemq
.ActiveMQConnectionFactory
.createActiveMQConnection(ActiveMQConnectionFactory.java:256)
at
org
.apache
.activemq
.ActiveMQConnectionFactory
.createConnection(ActiveMQConnectionFactory.java:182)
at
org
.apache
.activemq
.ra
.ActiveMQConnectionSupport
.makeConnection(ActiveMQConnectionSupport.java:79)
at
org
.apache
.activemq
.ra
.ActiveMQConnectionSupport
.makeConnection(ActiveMQConnectionSupport.java:61)
at
org
.apache
.activemq
.ra
.ActiveMQManagedConnectionFactory
.createManagedConnection(ActiveMQManagedConnectionFactory.java:169)
at
org
.apache
.geronimo
.connector
.outbound
.MCFConnectionInterceptor.getConnection(MCFConnectionInterceptor.java:
48)
at
org
.apache
.geronimo
.connector
.outbound
.XAResourceInsertionInterceptor
.getConnection(XAResourceInsertionInterceptor.java:41)
at
org
.apache
.geronimo
.connector
.outbound
.SinglePoolConnectionInterceptor
.internalGetConnection(SinglePoolConnectionInterceptor.java:67)
- locked <0x07ede778> (a
org.apache.geronimo.connector.outbound.SinglePoolConnectionInterceptor
$PoolDeque)
at
org
.apache
.geronimo
.connector
.outbound
.AbstractSinglePoolConnectionInterceptor
.getConnection(AbstractSinglePoolConnectionInterceptor.java:78)
at
org
.apache
.geronimo
.connector
.outbound
.TransactionEnlistingInterceptor
.getConnection(TransactionEnlistingInterceptor.java:46)
at
org
.apache
.geronimo
.connector
.outbound
.TransactionCachingInterceptor
.getConnection(TransactionCachingInterceptor.java:94)
at
org
.apache
.geronimo
.connector
.outbound
.ConnectionHandleInterceptor
.getConnection(ConnectionHandleInterceptor.java:43)
at
org
.apache
.geronimo
.connector.outbound.TCCLInterceptor.getConnection(TCCLInterceptor.java:
39)
at
org
.apache
.geronimo
.connector
.outbound
.ConnectionTrackingInterceptor
.getConnection(ConnectionTrackingInterceptor.java:66)
at
org
.apache
.geronimo
.connector
.outbound
.AbstractConnectionManager
.allocateConnection(AbstractConnectionManager.java:87)
at
org
.apache
.activemq
.ra
.ActiveMQConnectionFactory
.createConnection(ActiveMQConnectionFactory.java:94)
at
org
.apache
.activemq
.ra
.ActiveMQConnectionFactory
.createConnection(ActiveMQConnectionFactory.java:67)
at
org
.apache.openejb.config.LocalClientTest.assertRefs(LocalClientTest.java:
140)
at
org.apache.openejb.config.LocalClientTest.test(LocalClientTest.java:118)
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:592)
at junit.framework.TestCase.runTest(TestCase.java:168)
at junit.framework.TestCase.runBare(TestCase.java:134)
at junit.framework.TestResult$1.protect(TestResult.java:110)
at junit.framework.TestResult.runProtected(TestResult.java:128)
at junit.framework.TestResult.run(TestResult.java:113)
at junit.framework.TestCase.run(TestCase.java:124)
at junit.framework.TestSuite.runTest(TestSuite.java:232)
at junit.framework.TestSuite.run(TestSuite.java:227)
at
org
.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:
79)
at
org
.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:
62)
at
org
.apache
.maven
.surefire
.suite
.AbstractDirectoryTestSuite
.executeTestSet(AbstractDirectoryTestSuite.java:140)
at
org
.apache
.maven
.surefire
.suite
.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:165)
at org.apache.maven.surefire.Surefire.run(Surefire.java:107)
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:592)
at
org
.apache
.maven
.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:
289)
at
org
.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:
993)
Found 1 deadlock.
