glassfish
  1. glassfish
  2. GLASSFISH-20322

Configuration parsing (domain.xml) slows down server startup

    Details

    • Type: Bug Bug
    • Status: Open
    • Priority: Critical Critical
    • Resolution: Unresolved
    • Affects Version/s: 4.0_b84_RC1
    • Fix Version/s: 4.1
    • Component/s: hk2
    • Labels:
      None

      Description

      Parsing the domain.xml during server startup takes about 420 ms for 271 elements using 88 config bean classes. On the system where this was measured, system startup takes about 3400 ms, so domain.xml parsing is about 8% of the startup time. Of this 420 ms, about 275 is spent in DomainXml.parseDomainXml.

      Much of the DomainXml.parseDomainXml time is spent loading the classes. Just the parsing part (based on measuring MiniXmlParser) takes about 25 ms. The current parser is tightly coupled to the use of the model, which is derived from the config bean class. To make this parallel, this would need to be separated. The XML document would need to be parsed to determine the list of needed config bean models and the data to populate the Dom objects (stored in a form that is independent of the model). Then, using multiple threads, the config bean classes could be loaded and the Dom objects created. In addition to class loading, whenever a config bean is created, there is a call to the GlassFishConfigBean.initializationCompleted method which calls the AMX PendingConfigBeans class to add the config bean to a queue that is used by AMX if/when it initializes.

      The time outside of parseDomainXml (about 145 ms) is spent in the decorate method which adds indices to the service locator for various config objects.

      This issue is for exploring and implementing ways to reduce the time needed to parse the domain.xml with the goal of improving the server startup time.

        Activity

        Hide
        Tom Mueller added a comment -

        Still working on this for 4.0.

        Show
        Tom Mueller added a comment - Still working on this for 4.0.
        Hide
        Tom Mueller added a comment -

        A possible improvement:

        The TranslatedConfigView.getProxy method (in the nucleus/admin/config-api module) creates a new proxy every time it is called even though proxies are immutable objects. If it caches proxy objects, the hit rate is fairly high. However, most of the time is spent creating a proxy the first time. Creating a proxy the second time is about 10-40 microseconds whereas creating a proxy the first time can take milliseconds. So the savings from caching proxies is only a few milliseconds for the entire startup process.

        Here's a diff for adding a proxy cache:

        --- Base (BASE)
        +++ Locally Modified (Based On LOCAL)
        @@ -57,6 +57,9 @@
         import java.security.UnrecoverableKeyException;
         import java.security.cert.CertificateException;
         import java.io.IOException;
        +import java.lang.reflect.InvocationHandler;
        +import java.util.HashMap;
        +import java.util.Map;
         
         /**
          * View that translate configured attributes containing properties like ${foo.bar}
        @@ -67,6 +70,7 @@
         public class TranslatedConfigView implements ConfigView {
         
             final static Pattern p = Pattern.compile("([^\\$]*)\\$\\{([^\\}]*)\\}([^\\$]*)");
        +    final static Map<ProxyKey,Object> proxyCache = new HashMap<ProxyKey,Object>();
         
             private static final String ALIAS_TOKEN = "ALIAS";
             private static int MAX_SUBSTITUTION_DEPTH = 100;
        @@ -147,9 +151,23 @@
         
             @Override
             public <T extends ConfigBeanProxy> T getProxy(Class<T> proxyType) {
        -        return proxyType.cast(Proxy.newProxyInstance(proxyType.getClassLoader(), new Class[]{proxyType},
        -                 this));
        +        ProxyKey pk = new ProxyKey(proxyType, this);
        +        synchronized (proxyCache) {
        +            Object proxy = proxyCache.get(pk);
        +            if (proxy == null) {
        +                //long s = System.nanoTime();
        +                proxy = Proxy.newProxyInstance(proxyType.getClassLoader(), new Class[]{proxyType},
        +                     this);
        +                proxyCache.put(pk, proxy);
        +                //long e = System.nanoTime(); 
        +                //System.out.println("TranslatedConfigView.getProxy miss " + proxyType.getName() + " " + this + " " + (e-s)/1000);
        +            } else {
        +                //System.out.println("TranslatedConfigView.getProxy hit " + proxyType.getName() + " " + this);
             }
        +            return proxyType.cast(proxy);
        +        }
        +    }
        +    
             static ServiceLocator habitat;
             public static void setHabitat(ServiceLocator h) {
                  habitat = h;
        @@ -204,4 +222,39 @@
                }
         
             
        +    static class ProxyKey { 
        +        private Class aClass;
        +        private InvocationHandler handler;
        +        
        +        public ProxyKey(Class c, InvocationHandler h) {
        +            aClass = c;
        +            handler = h;
         }
        +
        +        @Override
        +        public boolean equals(Object obj) {
        +            if (obj == null) {
        +                return false;
        +            }
        +            if (getClass() != obj.getClass()) {
        +                return false;
        +            }
        +            final ProxyKey other = (ProxyKey) obj;
        +            if (this.aClass != other.aClass && (this.aClass == null || !this.aClass.equals(other.aClass))) {
        +                return false;
        +            }
        +            if (this.handler != other.handler && (this.handler == null || !this.handler.equals(other.handler))) {
        +                return false;
        +            }
        +            return true;
        +        }
        +        
        +        @Override
        +        public int hashCode() {
        +            int hash = 3;
        +            hash = 29 * hash + (this.aClass != null ? this.aClass.hashCode() : 0);
        +            hash = 29 * hash + (this.handler != null ? this.handler.hashCode() : 0);
        +            return hash;
        +        }
        +    }
        +}
        
        
        Show
        Tom Mueller added a comment - A possible improvement: The TranslatedConfigView.getProxy method (in the nucleus/admin/config-api module) creates a new proxy every time it is called even though proxies are immutable objects. If it caches proxy objects, the hit rate is fairly high. However, most of the time is spent creating a proxy the first time. Creating a proxy the second time is about 10-40 microseconds whereas creating a proxy the first time can take milliseconds. So the savings from caching proxies is only a few milliseconds for the entire startup process. Here's a diff for adding a proxy cache: --- Base (BASE) +++ Locally Modified (Based On LOCAL) @@ -57,6 +57,9 @@ import java.security.UnrecoverableKeyException; import java.security.cert.CertificateException; import java.io.IOException; + import java.lang.reflect.InvocationHandler; + import java.util.HashMap; + import java.util.Map; /** * View that translate configured attributes containing properties like ${foo.bar} @@ -67,6 +70,7 @@ public class TranslatedConfigView implements ConfigView { final static Pattern p = Pattern.compile( "([^\\$]*)\\$\\{([^\\}]*)\\}([^\\$]*)" ); + final static Map<ProxyKey, Object > proxyCache = new HashMap<ProxyKey, Object >(); private static final String ALIAS_TOKEN = "ALIAS" ; private static int MAX_SUBSTITUTION_DEPTH = 100; @@ -147,9 +151,23 @@ @Override public <T extends ConfigBeanProxy> T getProxy( Class <T> proxyType) { - return proxyType. cast (Proxy.newProxyInstance(proxyType.getClassLoader(), new Class []{proxyType}, - this )); + ProxyKey pk = new ProxyKey(proxyType, this ); + synchronized (proxyCache) { + Object proxy = proxyCache.get(pk); + if (proxy == null ) { + // long s = System .nanoTime(); + proxy = Proxy.newProxyInstance(proxyType.getClassLoader(), new Class []{proxyType}, + this ); + proxyCache.put(pk, proxy); + // long e = System .nanoTime(); + // System .out.println( "TranslatedConfigView.getProxy miss " + proxyType.getName() + " " + this + " " + (e-s)/1000); + } else { + // System .out.println( "TranslatedConfigView.getProxy hit " + proxyType.getName() + " " + this ); } + return proxyType. cast (proxy); + } + } + static ServiceLocator habitat; public static void setHabitat(ServiceLocator h) { habitat = h; @@ -204,4 +222,39 @@ } + static class ProxyKey { + private Class aClass; + private InvocationHandler handler; + + public ProxyKey( Class c, InvocationHandler h) { + aClass = c; + handler = h; } + + @Override + public boolean equals( Object obj) { + if (obj == null ) { + return false ; + } + if (getClass() != obj.getClass()) { + return false ; + } + final ProxyKey other = (ProxyKey) obj; + if ( this .aClass != other.aClass && ( this .aClass == null || ! this .aClass.equals(other.aClass))) { + return false ; + } + if ( this .handler != other.handler && ( this .handler == null || ! this .handler.equals(other.handler))) { + return false ; + } + return true ; + } + + @Override + public int hashCode() { + int hash = 3; + hash = 29 * hash + ( this .aClass != null ? this .aClass.hashCode() : 0); + hash = 29 * hash + ( this .handler != null ? this .handler.hashCode() : 0); + return hash; + } + } +}
        Hide
        Tom Mueller added a comment -

        Here is a summary of what we have found out so far concerning domain.xml parsing.

        Of the 420 ms spent in 4.0 (254 ms more than 3.1.2):

        • 6 ms is spent calling getAllServices(ConfigBeanListener.class) rather than getComponent(CageBuilder.class, "PendingConfigBeans");
        • 58 ms is spent processing config beans that were not there in 3.1.2
        • 51 ms is spent getting the implementation class for 3 config beans (I have not confirmed this, but I expect this is not done as part of domain.xml parsing in 3.1.2)
        • 50 ms is spent calling Config.addIndex (time is spent creating proxies that were not created as part of domain.xml parsing before)

        This accounts for 175 ms of the 254 ms.

        Show
        Tom Mueller added a comment - Here is a summary of what we have found out so far concerning domain.xml parsing. Of the 420 ms spent in 4.0 (254 ms more than 3.1.2): 6 ms is spent calling getAllServices(ConfigBeanListener.class) rather than getComponent(CageBuilder.class, "PendingConfigBeans"); 58 ms is spent processing config beans that were not there in 3.1.2 51 ms is spent getting the implementation class for 3 config beans (I have not confirmed this, but I expect this is not done as part of domain.xml parsing in 3.1.2) 50 ms is spent calling Config.addIndex (time is spent creating proxies that were not created as part of domain.xml parsing before) This accounts for 175 ms of the 254 ms.
        Hide
        Mahesh Kannan added a comment -

        Part of the problem is that Dom.register calls:
        ctrs.add(myselfReified.getImplementationClass());

        Which basically loads the class and hence activates the bundle. Maybe,
        we should explore if the above can be avoided. Probably we should just
        store the implementation class name (as opposed to storing implementation
        class itself).

        Having said that, this is too risky to make any changes to the config system so
        late in the release cycle.

        Show
        Mahesh Kannan added a comment - Part of the problem is that Dom.register calls: ctrs.add(myselfReified.getImplementationClass()); Which basically loads the class and hence activates the bundle. Maybe, we should explore if the above can be avoided. Probably we should just store the implementation class name (as opposed to storing implementation class itself). Having said that, this is too risky to make any changes to the config system so late in the release cycle.
        Hide
        Mahesh Kannan added a comment -

        Since this is a risky fix, marking this for 4.0.1

        Show
        Mahesh Kannan added a comment - Since this is a risky fix, marking this for 4.0.1

          People

          • Assignee:
            Mahesh Kannan
            Reporter:
            Tom Mueller
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated: