7 Replies Latest reply on Jun 21, 2010 5:51 PM by alesj

Endless loop at AS server startup

thomas.diesler Jun 11, 2010 3:01 AM

Using the latest framework together with jboss-cl-2.2.0.Alpha5 gets into an endless loop

https://jira.jboss.org/browse/JBOSGI-341

at org.jboss.osgi.framework.deployers.OSGiDeployersWrapper.change(OSGiDeployersWrapper.java:179)
    at org.jboss.deployers.plugins.main.MainDeployerImpl.change(MainDeployerImpl.java:732)
    at org.jboss.deployers.plugins.classloading.DeploymentLifeCycle.resolve(DeploymentLifeCycle.java:82)
    at org.jboss.classloading.spi.dependency.Domain.resolveModule(Domain.java:264)
    at org.jboss.classloading.spi.dependency.Module.resolveModule(Module.java:1335)
    at org.jboss.classloading.spi.dependency.ClassLoadingSpace.resolve(ClassLoadingSpace.java:332)
    - locked <0x00007fb7a16bc458> (a org.jboss.classloading.spi.dependency.ClassLoadingSpace)
    at org.jboss.classloading.spi.dependency.Module.resolveModule(Module.java:1332)
    at org.jboss.classloading.spi.dependency.RequirementDependencyItem.resolve(RequirementDependencyItem.java:119)
    at org.jboss.dependency.plugins.AbstractDependencyInfo.resolveDependencies(AbstractDependencyInfo.java:434)
    at org.jboss.dependency.plugins.AbstractController.resolveDependencies(AbstractController.java:1434)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1398)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1205)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1137)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:937)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:652)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:2008)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:764)
    at org.jboss.osgi.framework.deployers.OSGiDeployersWrapper.change(OSGiDeployersWrapper.java:180)
    at org.jboss.deployers.plugins.main.MainDeployerImpl.change(MainDeployerImpl.java:732)
    at org.jboss.deployers.plugins.classloading.DeploymentLifeCycle.resolve(DeploymentLifeCycle.java:82)
    at org.jboss.classloading.spi.dependency.Domain.resolveModule(Domain.java:264)
    at org.jboss.classloading.spi.dependency.Module.resolveModule(Module.java:1335)
    at org.jboss.classloading.spi.dependency.ClassLoadingSpace.resolve(ClassLoadingSpace.java:332)
    - locked <0x00007fb7a16bc458> (a org.jboss.classloading.spi.dependency.ClassLoadingSpace)
    at org.jboss.classloading.spi.dependency.Module.resolveModule(Module.java:1332)
    at org.jboss.classloading.spi.dependency.RequirementDependencyItem.resolve(RequirementDependencyItem.java:119)
    at org.jboss.dependency.plugins.AbstractDependencyInfo.resolveDependencies(AbstractDependencyInfo.java:434)
    at org.jboss.dependency.plugins.AbstractController.resolveDependencies(AbstractController.java:1434)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1398)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1205)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1137)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:937)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:652)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:2008)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:764)
    at org.jboss.osgi.framework.deployers.OSGiDeployersWrapper.change(OSGiDeployersWrapper.java:180)
    at org.jboss.deployers.plugins.main.MainDeployerImpl.change(MainDeployerImpl.java:732)
    at org.jboss.deployers.plugins.classloading.DeploymentLifeCycle.resolve(DeploymentLifeCycle.java:82)
    at org.jboss.classloading.spi.dependency.Domain.resolveModule(Domain.java:264)
    at org.jboss.classloading.spi.dependency.Module.resolveModule(Module.java:1335)
    at org.jboss.classloading.spi.dependency.RequirementDependencyItem.resolve(RequirementDependencyItem.java:119)
    at org.jboss.dependency.plugins.AbstractDependencyInfo.resolveDependencies(AbstractDependencyInfo.java:434)
    at org.jboss.dependency.plugins.AbstractController.resolveDependencies(AbstractController.java:1434)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1398)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1205)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1137)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:937)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:652)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:2008)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:764)
    at org.jboss.osgi.framework.deployers.OSGiDeployersWrapper.change(OSGiDeployersWrapper.java:180)
    at org.jboss.deployers.plugins.main.MainDeployerImpl.change(MainDeployerImpl.java:732)
    at org.jboss.deployers.plugins.classloading.DeploymentLifeCycle.resolve(DeploymentLifeCycle.java:82)
    at org.jboss.classloading.spi.dependency.Domain.resolveModule(Domain.java:264)
    at org.jboss.classloading.spi.dependency.Module.resolveModule(Module.java:1335)
    at org.jboss.classloading.spi.dependency.ClassLoadingSpace.resolve(ClassLoadingSpace.java:332)
    - locked <0x00007fb7a16bc458> (a org.jboss.classloading.spi.dependency.ClassLoadingSpace)
    at org.jboss.classloading.spi.dependency.Module.resolveModule(Module.java:1332)
    at org.jboss.classloading.spi.dependency.RequirementDependencyItem.resolve(RequirementDependencyItem.java:119)
    at org.jboss.dependency.plugins.AbstractDependencyInfo.resolveDependencies(AbstractDependencyInfo.java:434)
    at org.jboss.dependency.plugins.AbstractController.resolveDependencies(AbstractController.java:1434)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1398)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1205)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1137)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:937)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:652)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:2008)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:764)
    at org.jboss.osgi.framework.deployers.OSGiDeployersWrapper.change(OSGiDeployersWrapper.java:180)
    at org.jboss.deployers.plugins.main.MainDeployerImpl.change(MainDeployerImpl.java:732)
    at org.jboss.deployers.plugins.classloading.DeploymentLifeCycle.resolve(DeploymentLifeCycle.java:82)
    at org.jboss.classloading.spi.dependency.Domain.resolveModule(Domain.java:264)
    at org.jboss.classloading.spi.dependency.Module.resolveModule(Module.java:1335)
    at org.jboss.classloading.spi.dependency.ClassLoadingSpace.resolve(ClassLoadingSpace.java:332)
    - locked <0x00007fb7a16bc458> (a org.jboss.classloading.spi.dependency.ClassLoadingSpace)
    at org.jboss.classloading.spi.dependency.Module.resolveModule(Module.java:1332)
    at org.jboss.classloading.spi.dependency.RequirementDependencyItem.resolve(RequirementDependencyItem.java:119)
    at org.jboss.dependency.plugins.AbstractDependencyInfo.resolveDependencies(AbstractDependencyInfo.java:423)
    at org.jboss.dependency.plugins.AbstractController.resolveDependencies(AbstractController.java:1434)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1398)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1205)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1137)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:937)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:652)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:2008)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.change(DeployersImpl.java:764)
    at org.jboss.osgi.framework.deployers.OSGiDeployersWrapper.change(OSGiDeployersWrapper.java:180)
    at org.jboss.deployers.plugins.main.MainDeployerImpl.change(MainDeployerImpl.java:732)
    at org.jboss.osgi.framework.packageadmin.PackageAdminImpl.advanceBundlesToClassloader(PackageAdminImpl.java:392)
    at org.jboss.osgi.framework.packageadmin.PackageAdminImpl.resolveBundles(PackageAdminImpl.java:366)
    at org.jboss.osgi.framework.deployers.OSGiDeployersWrapper.afterDeployersProcess(OSGiDeployersWrapper.java:150)
    at org.jboss.osgi.framework.deployers.OSGiDeployersWrapper.process(OSGiDeployersWrapper.java:104)
    at org.jboss.deployers.plugins.main.MainDeployerImpl.process(MainDeployerImpl.java:679)
    at org.jboss.system.server.profileservice.deployers.MainDeployerPlugin.process(MainDeployerPlugin.java:106)

An update of jboss-cl to the latest snapshot does not work out of the box because if breaks several jbosgi-framework tests. The latter shows, that the jboss-cl testsuite is not comprehensive enough with respect to osgi use cases. The issue is not related to the felix resolver - i.e. it also shows up with no resolver in place.

I'll find out why this is looping and try to reproduce in the framework testsuite.

1. Re: Endless loop at AS server startup

thomas.diesler Jun 16, 2010 6:36 AM (in response to thomas.diesler)

The cause of this issue is in the ineficiency of MC module resolution. The loop is probably not endless but may run for a very-very long time.

#1 AbstractDependencyInfo.resolveDependencies(Controller, ControllerState) 
   
   // Iterates over all unresolved dependencies and calls #2 for each
   // REturns false for the first unresolved RDI

#2 RequirementDependencyItem.resolve(Controller)

   // Resolve the RDI by calling #3 with resolveClassSpace == true
   // If there is no matching Module return null
   // Handle Module self dependencies
   // Use semiresolve for non-self dependencies
   // Return false when semiResolve fails

#3 OSGiModule(Module).resolveModule(RequirementDependencyItem, boolean)

   // Resolves the Module in the ClasssLoadingSpace by calling #4
   // Resolves the Requirement in the Domain by calling #5

#4 ClassLoadingSpace.resolve(Module)

   // Iterate over all unresolved Module dependencies
   // Resolve the RDI by calling #3 with resolveClassSpace == false
   // If a module was found join and resolve the ClassSpace

#5 Domain.resolveModule(Module, Requirement)

   // Iterates over all Modules
   // For each Module iterate over all its Capabilities
   // For each Capability check if it matches the given requirement
   // Return the first module that matches the requirement

So for each unresolved requirement we iterate again over all unresolved requirements. The inner loop again iterates over all modules and all capabilities.

For a module that has many requirements, like the OSGi compendium.jar, this takes forever when we run in a container with many modules.

I introduced a cache in the Module that maps a Requirement to the Module that sattisfies it

protected Module resolveModule(RequirementDependencyItem dependency, boolean resolveSpace)
   {
      Requirement requirement = dependency.getRequirement();
      Module otherModule = requirementProviderCache.get(requirement);
      if (otherModule == null)
      {
         // Resolving this module in the class loading space
         ClassLoadingSpace space = getClassLoadingSpace();
         if (resolveSpace && space != null)
            space.resolve(this);

         // Recheck the cache in case the provider for the requirement
         // was found during the above class space resolve step 
         otherModule = requirementProviderCache.get(requirement);
         if (otherModule == null)
         {
            // Resolve the requirement in the domain and cache the providing module 
            otherModule = checkDomain().resolveModule(this, requirement);
            if (otherModule != null)
               requirementProviderCache.put(requirement, otherModule);
         }
      }
      return otherModule;
   }

The cache is cleared in

* Module.removeDependencies

* Module.unresolveDependencies()

* Module.reset()

In the test case I could not generate a failure. However, AS now starts up and resolves all the OSGi bundles with this cache in place.

2. Re: Endless loop at AS server startup

alesj Jun 16, 2010 6:38 AM (in response to thomas.diesler)

The cache is cleared in

* Module.removeDependencies
* Module.unresolveDependencies()
* Module.reset()
Dunno if this needs to be cleared 3 times.
It probably can't hurt, but it's inconsistent. We should just find the right place.
Actions
3. Re: Endless loop at AS server startup

thomas.diesler Jun 16, 2010 6:41 AM (in response to thomas.diesler)

The cache may have side effects because the code in #4 and #5 is not always executed when a client calls #3.

Could you please review carefully or alternatively change the algorithm so it becomes usable for large sets of reqs/caps and mods.
Perhaps these large sets should be mocked in the CL testsuite.
Actions
4. Re: Endless loop at AS server startup

alesj Jun 16, 2010 6:45 AM (in response to thomas.diesler)

Perhaps these large sets should be mocked in the CL testsuite.
Any idea or suggestion on how to properly mock such large set?
e.g. so we actually have a resolvable aka valid large set
Actions
5. Re: Endless loop at AS server startup

thomas.diesler Jun 16, 2010 7:13 AM (in response to alesj)
I can't say that I understand the issue fully. When the AbstractDependencyInfo returns it's unresolved requirements - it is an unordered set. So the order of the requirements is not deterministic.

In AS we currently distribute these bundles

jboss-osgi-blueprint.jar jboss-osgi-common-core.jar jboss-osgi-common.jar jboss-osgi-http.jar jboss-osgi-husky.jar jboss-osgi-jaxb.jar jboss-osgi-jmx.jar jboss-osgi-jndi.jar jboss-osgi-reflect.jar jboss-osgi-webapp.jar jboss-osgi-webconsole.jar jboss-osgi-xerces.jar jboss-osgi-xml-binding.jar org.apache.aries.jmx.jar org.apache.aries.util.jar org.apache.felix.eventadmin.jar org.apache.felix.log.jar org.osgi.compendium.jar

They come with mandatory/optional and of course dynamic requirements. One possibility could be to add a few "special" log messages that write an audit log to a dedicated appender. The test case could extract the module + caps + reqs topology from the log and build up the metadata from it.

I believe, it is a resolve time problem only - so there should be no actual class load needed.

The standalone Runtime BTW resolves these bundles in a timely manner even without the cache. One reason could be that the compendium and a few other key bundles are installed/resolved first before the others come in. Another reason is that we only deal with OSGi modules, which is unlike in AS where we have very many modules with an unknown set of caps/reqs.

I might also add, that I'm not sure that the algorithm (without the cache) does not run into an endless loop after all - in contrary I suspect it does, but I haven't seen it in a test case. I'm however fairly sure that the cache would prevent that.
Actions

6. Re: Endless loop at AS server startup

alesj Jun 21, 2010 5:40 PM (in response to thomas.diesler)

The cache may have side effects because the code in #4 and #5 is not always executed when a client calls #3.

Could you please review carefully or alternatively change the algorithm so it becomes usable for large sets of reqs/caps and mods.

Adding this patch doesn't change AS boot time in measurable way, at least not for default and all.

Index: classloading/src/main/java/org/jboss/classloading/spi/dependency/Module.java
===================================================================
--- classloading/src/main/java/org/jboss/classloading/spi/dependency/Module.java    (revision 106215)
+++ classloading/src/main/java/org/jboss/classloading/spi/dependency/Module.java    (working copy)
@@ -85,6 +85,9 @@
    
    /** The requirements */
    private List<RequirementDependencyItem> requirementDependencies;
+   
+   /** Already resolved dependency items */
+   private Map<RequirementDependencyItem, Module> resolved;
 
    /** Any lifecycle associated with the classloader */
    private LifeCycle lifeCycle;
@@ -94,7 +97,7 @@
    
    /** Requirements resolved to us */
    private Set<RequirementDependencyItem> depends = new CopyOnWriteArraySet<RequirementDependencyItem>();
-   
+
    /**
     * Register a classloader for a module
     * 
@@ -1191,6 +1194,7 @@
             addIDependOn(item);
             requirementDependencies.add(item);
          }
+         resolved = new ConcurrentHashMap<RequirementDependencyItem, Module>();
       }
    }
 
@@ -1205,6 +1209,7 @@
             removeIDependOn(item);
       }
       requirementDependencies = null;
+      resolved = null;
    }
 
    /**
@@ -1216,7 +1221,10 @@
       if (requirementDependencies != null && requirementDependencies.isEmpty() == false)
       {
          for (RequirementDependencyItem item : requirementDependencies)
+         {
             item.unresolved(controller);
+            resolved.remove(item);
+         }
       }
    }
 
@@ -1336,14 +1344,33 @@
     */
    protected Module resolveModule(RequirementDependencyItem dependency, boolean resolveSpace)
    {
+      if (resolved != null)
+      {
+         Module resolvedModule = resolved.get(dependency);
+         if (resolvedModule != null)
+            return resolvedModule;
+      }
+
       ClassLoadingSpace space = getClassLoadingSpace();
       if (resolveSpace && space != null)
          space.resolve(this);
 
+      if (resolved != null)
+      {
+         Module resolvedModule = resolved.get(dependency);
+         if (resolvedModule != null)
+            return resolvedModule;
+      }
+
       Requirement requirement = dependency.getRequirement();
-      return checkDomain().resolveModule(this, requirement);
+      Module result = checkDomain().resolveModule(this, requirement);
+
+      if (result != null && resolved != null)
+         resolved.put(dependency, result);
+
+      return result;
    }

Perhaps these large sets should be mocked in the CL testsuite.

But I guess, as you mentioned, it will only show in osgi config, with compendium's large requirement set.

7. Re: Endless loop at AS server startup

alesj Jun 21, 2010 5:51 PM (in response to alesj)
The cache may have side effects because the code in #4 and #5 is not always executed when a client calls #3.

Could you please review carefully or alternatively change the algorithm so it becomes usable for large sets of reqs/caps and mods.
Adding this patch doesn't change AS boot time in measurable way, at least not for default and all.
This is expected, since basic AS deployments don't have any explicit requirements,
hence no RequirementDependencyItems are created --> nothing to resolve.

/** * Create the dependencies for the module */ protected void createDependencies() { ControllerState classLoaderState = getClassLoaderState(); List<Requirement> requirements = getRequirements(); if (requirements != null) {
Actions

Go to original post