Comment 1 Alexandre Vasseur 2005-06-14 09:37:43 EDT

Created attachment 23048 [details]
thread dump (clean EOL)

Comment 2 Alexandre Vasseur 2005-06-14 09:46:54 EDT

from the dump:

Thread-main is starting its job and some reflective invocation leads to creation
of JDK proxy that leads to Sun Unsafe.defineClass(...) (explicit class load)
This call goes into the VM, and then back in the JVMTI AJ agent that then locks
the AJ aop.xml "definition" repository.
The defining ClassLoader is not locked by Sun Unsafe stuff.

At some point Thread-x has been started. During its execution this one triggers
implicit class load. This ones goes in the JDK ClassLaoder.loadClass that locks
the defining ClassLoader.
This one then reach the JVMTI agent and waits for the AJ repository.

Two locks have been obtained in 2 different order hence the deadlock.
-----

I think I can fix that by enforcing a manual (synchronized(laoder) {}) before
locking the AJ repository but that s really BAD.
I think the issue comes from Unsafe that happens to be broken since it does goes
to JVMTI without locking the loader.

My assumption is that this should be a SUN JDK bug, easily reproduced outside of
AJ (write a JVMTI agent, write a main that forks a thread that keeps working
(say do Class.forName() given a long list of stuff from some jar)), and in the
main (after thread fork) call some stuff to gen a proxy and go into the agent
thru Sun Unsafe.defineClass.
In the agent then lock on whatever object you like. You 'll get the deadlock.

JVMTI does not say "don't lock anything" (else give me the link and the quote)
so this is Sun bug.
Going fine in JRockit is another evidence I guess.
In the branch you can perhaps check but perhaps I was not locking the repository
(which is not safe).

comments ?

Comment 3 Ron Bodkin 2005-06-14 17:01:48 EDT

I'm willing to believe this is a Sun JVMTI implementation bug, but I think 
it's really important that AspectJ continue to work-around bugs in the Sun 
VMs. Even if Sun fixes this in a future release, it's still important to 
support the leading VM, bugs and all.

I'm guessing that I didn't see this bug earlier because you weren't locking 
the repository in an earlier release?

Would the work-around add a risk of other deadlocks? Would it materially harm 
performance?

Comment 4 Alexandre Vasseur 2005-06-15 10:45:14 EDT

You perhaps can try and check.
I don't want a workaround in the long run.

It would be interesting to see what is in the Sun bug database and if you find
something link the Sun bug here.

Comment 5 Ron Bodkin 2005-07-04 16:11:19 EDT

I was going to try the work around but the latest version in CVS head is 
giving me a verify error. I'm assuming that it's just an instability in the 
run up to M3 (since other things from the CVS HEAD version are causing me 
problems too), and I'll wait until things are a little more stable to try 
again.

Comment 6 Alexandre Vasseur 2005-07-05 04:39:17 EDT

I am not aware of such a verify error

Please report a bug so that we can reproduce, track and fix (or refer to it if
you know it is a known bug)

Comment 7 Ron Bodkin 2005-07-05 12:56:46 EDT

I was able to get everything to build & run today (*), and your proposed work-
around fixes the problem on a Sun 1.5.0_02 JVM. The resulting code continues 
to work on JRockIt 1.5.0_02. I think integrating the workaround into HEAD 
would make sense. Perhaps if Sun fixes this issue, it could be included only 
on the specific VM's with the problem.

I made this one change to CVS HEAD:

Starting at Aj.java:76
        static WeavingAdaptor getWeaver(ClassLoader loader) {
        	synchronized (loader) {
	            synchronized (weavingAdaptors) {
...
                    }
                }
        }


(*) Either the verify error was caused by my not seeing error output from ant 
(a bug I just submitted) or one of the changes checked in today fixed it for 
me.

Comment 8 Alexandre Vasseur 2005-07-11 11:10:58 EDT

ok patch is in cvs
let the issue open, to see how it goes
(ie M3 will ship with this hack hence assigned to M4)

Comment 9 Adrian Colyer 2005-09-27 05:58:12 EDT

raising to P2

Comment 10 Alexandre Vasseur 2005-09-28 09:33:13 EDT

see 109334 that is a consequence of the horrible hack here

only option is to fine a Sun 1.5 VM that has not the JSR 163 bug and only
support this one and more recent ones.

Comment 11 Alexandre Vasseur 2005-10-10 05:04:16 EDT

Ron please comment

I can't reproduce it from a simpler agent to post a Sun bug report.
That said perhaps we can avoid this by having a postInit() method that is called
after the synchrnoized block, or by having a doNothingWeavingAdaptor() as long
as we are in the middle of initializing the adaptor - to avoid this kind of
reentrancy. ie:

static WeavingAdaptor getWeaver(ClassLoader loader, IWeavingContext
weavingContext) {
 synchronized (weavingAdaptors) {
    weavingAdaptor = (WeavingAdaptor) weavingAdaptors.get(loader);
    if (weavingAdaptor == null) {
        weavingAdaptor = new ClassLoaderWeavingAdaptor(loader, weavingContext);
        weavingAdaptors.put(loader, weavingAdaptor);
    }
  }
  // (extract local variable to make this compile off course)
  weavingAdaptor.postInit();//method to add, that does what <init> does right now
  // and that has a boolean like "isInit" to avoid multiple initialization

  // this call will trigger nested classloading but that should be fine.
  return weavingAdaptor;
}


this would ensure that no nested loading is done while lock is held.



Ron - can you send me detailled instructions / war on how to reproduce that with
a Tomcat 5.x? so that I can fix it once for all?

Comment 12 Ron Bodkin 2005-10-10 12:03:47 EDT

I think it would be great to move the initialization out of the synchronized 
block. Clearly this helps if you load resources from different classloaders. 
But if you are loading a resource from the same classloader, in the middle of 
initialization, how will you handle this? Obviously this would still be a big 
improvement.

You can download a buildable project that reproduces the problem (the pre-built 
jar is of course tied to a specific AspectJ compiler pre-M4 at this stage) from 
the glassbox inspector open source project: https://glassbox-
inspector.dev.java.net/servlets/ProjectDocumentList?
folderID=4064&expandFolder=4064&folderID=0. If you put the inspector jar in %
TOMCAT_HOME$\shared\lib then Tomcat locks up. I don't believe it depends on any 
applications being installed other than the standard pre-installed ones.

Comment 13 Ron Bodkin 2005-10-10 12:14:41 EDT

Naturally, if you do the refactoring to pull the init code out, I'd be glad to 
test it out.

Comment 14 Alexandre Vasseur 2005-10-11 04:23:47 EDT

D:\>echo %JAVA_HOME%
D:\java\jdk1.5.0_03
(ie Sun VM)
Tomcat 5.5, windows
drop the jars as you said in shared/lib
changed the script as described in readme

I can see message like
log4j:WARN No appenders could be found for logger (glassbox.inspector.config.Sim
pleConfig).
log4j:WARN Please initialize the log4j system properly.
So GlassBox is in. So far so good.

But HelloWorld JSP or Servlet OOT with Tomcat don't deadlock.
Please detail where I should click to have the deadlock.

Comment 15 Ron Bodkin 2005-10-11 06:57:59 EDT

Interesting. It must be loading an application on startup that causes the 
problem. I have attached a war file from a version of the jpetstore that should 
just cause it on start-up with no user interaction. You _might_ need to 
configure a database for this to happen, but I bet not.

Comment 16 Ron Bodkin 2005-10-11 07:02:05 EDT

Bugzilla won't accept the war file. I tried to send to you by email Alex. If 
that doesn't work please let me know & I'll ftp it somewhere for you.

Comment 17 Alexandre Vasseur 2005-10-11 07:20:33 EDT

got the war thru email - thx.

deployed in Tomcat, restart Tomcat
can see Glassbox jmx message
all startup sequence completes just fine

go to /jpetstore/
can see the home page
click on "enter the shop"
got exceptions due to jdbc driver not there
still no deadlock

- if you want I can commit the refactoring of AJ and you can rebuild it from a
cvs update and see what happens then.

Comment 18 Ron Bodkin 2005-10-11 07:27:26 EDT

Gak. That's weird, I and others have predictably seen this deadlock running in 
the Tomcat environment. I wonder what's different. Maybe just unrelated chnges 
in AspectJ are affecting a race condition?

Please do check in the refactored change and I'll rebuild, then try first 
straight the M4 version to see if I still see it on a Sun VM and then the 
refactored change. 

Comment 19 Ron Bodkin 2005-10-11 07:42:20 EDT

I am sorry I mispoke. You need to deploy the inspector to common/lib so it 
affects Tomcat itself! It works just fine in shared/lib (we changed the install 
docs to workaround this bug!!). Can you try that. You shouldn't even need the 
jpetstore.

Comment 20 Alexandre Vasseur 2005-10-11 10:40:37 EDT

ok can reproduce

with my patch it seems to startup fine now but I have BCException as I am using
a newer version of a weaver milestone

just commited a fix in CVS, module "loadtime" (Aj, ClassLoaderWeavingAdaptor .java)
can you rebuild AJ and give it a try?

Comment 21 Ron Bodkin 2005-10-13 06:46:30 EDT

This now runs unbelievably slowly on my machine and finally exhausts resources. 
It has the CPU pegged and after running about 20x as long I get these messages. 
I think it's in an infinite loop initializing somehow. I will attach the 
exception that finally occurs and a thread dump 30 seconds after startup

It seems to be incredibly slow reading in the aspects: you can't build up an 
aspect string byte by byte like this?! I optimized this by using a StringBuffer 
and it seems much faster and it didn't run out of memory as before. Now I too 
see BCException even though I did a rebuild. I will investigate this more. See 
attached patch that improved startup performance by 2 orders of magnitude...

Also, is it safe to have a race in initializing the classloader (e.g., on 
JRockit where the loader isn't locked?) Also, you should rename 
ExplicitlyInitializedClassLaoderWeavingAdaptor to fix a typo - it says LAODER 
not loader...

Exception:
Message: error problem loading XlintDefault.properties, oversubscribed dynamic b
it lengths tree
org.aspectj.bridge.AbortException: problem loading XlintDefault.properties, over
subscribed dynamic bit lengths tree
        at org.aspectj.weaver.tools.WeavingAdaptor$WeavingAdaptorMessageHandler.
handleMessage(WeavingAdaptor.java:318)
        at org.aspectj.bridge.MessageUtil.error(MessageUtil.java:80)
        at org.aspectj.weaver.Lint.loadDefaultProperties(Lint.java:129)
        at org.aspectj.weaver.tools.WeavingAdaptor.init(WeavingAdaptor.java:144)

        at org.aspectj.weaver.tools.WeavingAdaptor.<init>(WeavingAdaptor.java:82
)
        at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.<init>(ClassLoa
derWeavingAdaptor.java:61)
        at org.aspectj.weaver.loadtime.Aj$WeaverContainer.getWeaver(Aj.java:94)
        at org.aspectj.weaver.loadtime.Aj.preProcess(Aj.java:65)
        at org.aspectj.weaver.loadtime.ClassPreProcessorAgentAdapter.transform(C
lassPreProcessorAgentAdapter.java:52)
        at sun.instrument.TransformerManager.transform(TransformerManager.java:1
22)
        at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java
:155)
        at java.lang.ClassLoader.defineClass1(Native Method)
        at java.lang.ClassLoader.defineClass(ClassLoader.java:620)
        at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:12
4)
        at org.apache.catalina.loader.WebappClassLoader.findClassInternal(Webapp
ClassLoader.java:1629)
        at org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoa
der.java:850)
        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoa
der.java:1299)
        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoa
der.java:1181)
        at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
        at java.lang.Class.getDeclaredConstructors0(Native Method)
        at java.lang.Class.privateGetDeclaredConstructors(Class.java:2328)
        at java.lang.Class.getConstructor0(Class.java:2640)
        at java.lang.Class.newInstance0(Class.java:321)
        at java.lang.Class.newInstance(Class.java:303)
        at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.
java:1048)
        at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:92
5)
        at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContex
t.java:3857)
        at org.apache.catalina.core.StandardContext.start(StandardContext.java:4
118)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase
.java:759)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:73
9)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:524)

        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.ja
va:589)
        at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.j
ava:536)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:471
)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1102)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java
:311)
        at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(Lifecycl
eSupport.java:119)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1020)

        at org.apache.catalina.core.StandardHost.start(StandardHost.java:718)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1012)

        at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:442
)
        at org.apache.catalina.core.StandardService.start(StandardService.java:4
50)
        at org.apache.catalina.core.StandardServer.start(StandardServer.java:683
)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:537)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.
java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
sorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:271)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:409)

Full thread dump Java HotSpot(TM) Client VM (1.5.0_04-b05 mixed mode):

"Low Memory Detector" daemon prio=5 tid=0x26d44560 nid=0x1374 runnable [0x000000
00..0x00000000]

"CompilerThread0" daemon prio=10 tid=0x26d5daf0 nid=0x344 waiting on condition [
0x00000000..0x26f7f6cc]

"Signal Dispatcher" daemon prio=10 tid=0x26d2bad8 nid=0x1370 runnable [0x0000000
0..0x00000000]

"Finalizer" daemon prio=9 tid=0x00959230 nid=0xea0 in Object.wait() [0x26cff000.
.0x26cffa68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x051907e8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x051907e8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00957dd8 nid=0x45c in Object.wait() [0x
26cbf000..0x26cbfae8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x05190868> (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 <0x05190868> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=0x000365d8 nid=0x3f4 runnable [0x0007e000..0x0007fc3c]
        at java.lang.String.<init>(String.java:208)
        at java.lang.StringBuffer.toString(StringBuffer.java:586)
        - locked <0x053b84c0> (a java.lang.StringBuffer)
        at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.readAspect(Clas
sLoaderWeavingAdaptor.java:425)
        at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.registerAspects
(ClassLoaderWeavingAdaptor.java:262)
        at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.registerDefinit
ions(ClassLoaderWeavingAdaptor.java:157)
        at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.initialize(Clas
sLoaderWeavingAdaptor.java:110)
        at org.aspectj.weaver.loadtime.Aj$ExplicitlyInitializedClassLaoderWeavin
gAdaptor.initialize(Aj.java:130)
        at org.aspectj.weaver.loadtime.Aj$ExplicitlyInitializedClassLaoderWeavin
gAdaptor.getWeavingAdaptor(Aj.java:135)
        at org.aspectj.weaver.loadtime.Aj$WeaverContainer.getWeaver(Aj.java:100)

        at org.aspectj.weaver.loadtime.Aj.preProcess(Aj.java:65)
        at org.aspectj.weaver.loadtime.ClassPreProcessorAgentAdapter.transform(C
lassPreProcessorAgentAdapter.java:52)
        at sun.instrument.TransformerManager.transform(TransformerManager.java:1
22)
        at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java
:155)
        at java.lang.ClassLoader.defineClass1(Native Method)
        at java.lang.ClassLoader.defineClass(ClassLoader.java:620)
        at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:12
4)
        at java.net.URLClassLoader.defineClass(URLClassLoader.java:260)
        at java.net.URLClassLoader.access$100(URLClassLoader.java:56)
        at java.net.URLClassLoader$1.run(URLClassLoader.java:195)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:188)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
        - locked <0x05299ad0> (a org.apache.catalina.loader.StandardClassLoader)

        at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
        at org.apache.catalina.startup.Bootstrap.init(Bootstrap.java:198)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:386)

"VM Thread" prio=10 tid=0x0003ef50 nid=0xddc runnable

"VM Periodic Task Thread" prio=10 tid=0x26d436c0 nid=0x136c waiting on condition

Comment 22 Alexandre Vasseur 2005-10-14 12:29:36 EDT

yes I have seen some weird overload - even when only one thred is working.
In readAspect() stuff that is used for binary diff in reweavable mode - as far
as I understand what has been done in that area, we read stuff bytes by bytes
just to get sort of a hash.

I'll check some more what 's happening and will perhaps forward this issue to Andy.

[as a reminder, the test app is in my emails and cannot be attached to the bug
as it is too big]

Comment 23 Alexandre Vasseur 2005-10-24 05:35:44 EDT

readAspect was simplified
closing this one

Comment 24 Eclipse Webmaster 2009-08-30 02:49:57 EDT

LATER/REMIND bugs are being automatically reopened as P5 because the LATER and REMIND resolutions are deprecated.