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