1 2 Previous Next 29 Replies Latest reply: Oct 31, 2005 4:13 PM by Elias Ross RSS

JBAS-2393 - ClassLoading Deadlock

Adrian Brock Master

The real problem here is classloading doing "arbitrary" callouts via
unguarded debug logging.
We have no idea what people attach to logging and what it might do.

In this particular instance, the construction of a RepositoryClassLoader
was not anticipated to be done at "runtime".
In fact, it is used by the HierarchicalLoaderRepository to add a System
classloader above the isolated classes.

Aside: I don't see why this:

 // Include a class loader with a parent to the system class loader
 ClassLoader loader = RepositoryClassLoader.class.getClassLoader();
 RepositoryClassLoader ucl = null;
 if( loader instanceof RepositoryClassLoader )
 ucl = (RepositoryClassLoader) loader;
 else
 ucl = new UnifiedClassLoader3(null, null, HeirarchicalLoaderRepository3.this);
 PkgClassLoader pkgUcl = new PkgClassLoader(ucl, 3);

can't be done once at HLR construction?


  • 1. Re: JBAS-2393 - ClassLoading Deadlock
    Adrian Brock Master

    For this particular problem, it should be possible to workaround it
    by not logging classloading through the root logger, avoiding that object
    as a point of contention?

  • 2. Re: JBAS-2393 - ClassLoading Deadlock
    Scott Stark Master

     

    "adrian@jboss.org" wrote:

    Aside: I don't see why this:
     // Include a class loader with a parent to the system class loader
     ClassLoader loader = RepositoryClassLoader.class.getClassLoader();
     RepositoryClassLoader ucl = null;
     if( loader instanceof RepositoryClassLoader )
     ucl = (RepositoryClassLoader) loader;
     else
     ucl = new UnifiedClassLoader3(null, null, HeirarchicalLoaderRepository3.this);
     PkgClassLoader pkgUcl = new PkgClassLoader(ucl, 3);
    

    can't be done once at HLR construction?

    Hey, use the proper (misspelled HeirarchicalLoaderRepository3) next time or I can't find the class ;)

    Yes, this PkgClassLoader certainly could be built in the ctor and reused.

    In terms of this deadlock, our friend genman actually worked on a patch to fix this issue but I'm not sure it got into the codebase. We should at least look at it as a solution.

    In terms of avoiding the root category, its not clear how we can control this. Have you looked at the log4j source and know how?


  • 3. Re: JBAS-2393 - ClassLoading Deadlock
    Jim Paterson Newbie

    To clarify - your workaround is to add something like the following XML to log4j.xml





    Unfortunately I haven't got a reproducable test case yet to consistently create the deadlock so I can't confidently say this has fixed it. I have examined the Log4J source code and I think this should fix it. We are going to try this workaround and have some stress testing of our application planned in the next few days. If this reveals anything I will update this issue.

  • 4. Re: JBAS-2393 - ClassLoading Deadlock
    Jim Paterson Newbie

    Here is a second attempt at the XML refered to in my previous post:

     <category name="org.jboss.mx.loading" additivity="false">
     <priority value="OFF"/>
     </category>
    



  • 5. Re: JBAS-2393 - ClassLoading Deadlock
    Adrian Brock Master

    Or an appender link.

    It's alway hard to reproduce race conditions, unless you add code (like sleeps) to the
    critical sections to make it more likely. :-)

    You should be able to reproduce it by writing your own custom appender
    that tries to load a class.

    Concurrently, starting first,
    have something do some classloading in the same application
    on a different thread, very quickly in a loop.

    It won't always deadlock, but it should do after a few runs.
    The trick is for the appender to try the class load while the
    RepositoryClassLoader is attempting the debug statement.

    I'd personally just remove the debug statement than trust my ability to
    reproduce the deadlock reliably. :-)

  • 6. Re: JBAS-2393 - ClassLoading Deadlock
    Adrian Brock Master

     

    "scott.stark@jboss.org" wrote:

    In terms of this deadlock, our friend genman actually worked on a patch to fix this issue but I'm not sure it got into the codebase. We should at least look at it as a solution.


    Do you mean this or something else? http://jira.jboss.com/jira/browse/JBAS-2160


    In terms of avoiding the root category, its not clear how we can control this. Have you looked at the log4j source and know how?


    additivity=false

  • 7. Re: JBAS-2393 - ClassLoading Deadlock
    Scott Stark Master

    No, he created a patch for log4j itself. I'll check the log4j bug db. I just remember seeing some discussion of it on the log4j dev list.

  • 8. Re: JBAS-2393 - ClassLoading Deadlock
    Scott Stark Master

    Here is the log4j issue and patches that genman(Elias Ross) submitted and got no love for. We need to look at the latest version of the patches as there are a couple revs.

    http://issues.apache.org/bugzilla/show_bug.cgi?id=24159

  • 9. Re: JBAS-2393 - ClassLoading Deadlock
    Adrian Brock Master

    Although I agree with the sentiment of making the logging as least prone
    to error as possible, the example code

    class State {
     Logger log1;
    
     synchronized void setState() {
     // Something takes a long time here
     log.debug("hello world");
     }
    
     synchronized Object getState() {
     }
    
     public String toString() {
     return "state=" + getState();
     }
    }
    


    Suffers from the synchronize and callout problem without considering
    what the callout might do.

    Incidently, this is only going to occur if you do
    State myState = new State();
    log.debug(myState);
    


    This trivially avoids the problem at the expense of a String construction.
    State state = new State();
    log.debug(myState.toString());
    


  • 10. Re: JBAS-2393 - ClassLoading Deadlock
    Adrian Brock Master

    The deadlock I'm more aware of is appenders that do logging.
    e.g. using JBossMQ to jms appending
    logger -> appender -> logger
    is a deadlock scenario

  • 11. Re: JBAS-2393 - ClassLoading Deadlock
    Scott Stark Master

    You have looked at the patch and are saying the first usage still is subject to deadlock in the first case, or you are just speculating?

  • 12. Re: JBAS-2393 - ClassLoading Deadlock
    Adrian Brock Master

    No, I didn't look at the patch. I just saw the pattern:

    synchronize (this)
    {
     somethingElse.callout();
    }
    


    With other entry points also doing synchronization, e.g.
    what if somethingElse on a different entry point invokes "this"?
    i.e. locks in reverse order

    Which is exactly what is happening.
    Just because it is log4j, doesn't mean it is not subject to the rules of locking :-)

  • 13. Re: JBAS-2393 - ClassLoading Deadlock
    Scott Stark Master

    Yes, but the current problem seems to be rendering of the msg or exception with a lock held that is the problem. We need to know that no class/resource loading occurs from within the logging layer with a lock held.

  • 14. Re: JBAS-2393 - ClassLoading Deadlock
    Adrian Brock Master

    According to the bug report, at least the 1.3 patch is out-of-date,
    with some changes "in the right direction" in the 1.3 branch.

    Elias himself says the patches for 1.2 are "too disruptive".

    The thrust of the changes appears to be to do the rendering "Object.toString()"
    as late as possible while still maintaining thread safety and "correct behaviour".

    A side affect is more concurrency, although personally I think you've got a
    different problem anyway if you are worrying about the concurrency of the logging. :-)

1 2 Previous Next