11 Replies Latest reply on Oct 14, 2005 8:51 AM by aloubyansky

    Some profiling numbers

    bill.burke

      Emailed this to Adrian, but I'll post here for discussion. I think the numbers are very important especially for JUnit testing I did a profile of a simple Embeddable EJB3 app. Total time to 3.8 secs without profiling, but here's the breakdown after running through JProfiler.

      Downloaded JProfiler and profiled a simple standalone app with 1 Session bean and 1 Entity bean.

      66 % of time in bootstrapping basic services
      30% of time was taken in deploying the beans (EJB/Entity)

      Interesting break downs (% are in total profile)
      ----------------

      bootstrapping:

      28.7% of time was in creating all the org.jboss.reflect objects (getTypeInfo)
      15% of time was in getSchemaBinding for the MC
      6.3% of time was just calling org.jboss.logging.Logger.getLogger (1 invocation)
      5.7% unmarshalling all the bean.xml
      12.3% in actually deploying JBoss services
      7.1% in deploying the AOP XML

      EJB/Entity Deployment:

      20% HibernatePersistence.createEntityManagerFactory
      9.8% Creating the Session Bean.

      3% running the actual app.

      The most glaring numbers as far as MC is concerned is the huge time in creating the reflect objects. I still think these reflect objects are useless as all they do is copy directly from java.lang.reflect objects.

      The other is just loading up the schema and the creation of the Logger.

      Are we stuck or is there something we can do here?

        • 1. Re: Some profiling numbers
          starksm64

          This seems like a microbenchmark. Why do you think these number are significant?

          • 2. Re: Some profiling numbers
            • 3. Re: Some profiling numbers

              Getting JBossXB to use the same reflection model/cache would also
              remove some duplicate/inefficent work:

              [ejort@htimes2 binding]$ grep -ri getMethod *
              AbstractMarshaller.java: method = providerClass.getMethod(methodName, args);
              DelegatingObjectModelFactory.java: Method[] methods = typedFactory.getClass().getMethods();
              DelegatingObjectModelFactory.java: Method method = ObjectModelBuilder.getMethodForElement(typedFactory,
              DelegatingObjectModelFactory.java: Method method = ObjectModelBuilder.getMethodForElement(typedFactory,
              DelegatingObjectModelFactory.java: Method method = addMethods.getMethodForChild(child.getClass());
              DelegatingObjectModelFactory.java: Method method = ObjectModelBuilder.getMethodForElement(typedFactory,
              DelegatingObjectModelFactory.java: public Method getMethodForChild(Class child)
              MappingObjectModelFactory.java: getter = o.getClass().getMethod("get" + xmlToCls, null);
              MappingObjectModelFactory.java: getter = oCls.getMethod("get" + xmlToCls, null);
              MappingObjectModelFactory.java: getter = parentCls.getMethod("get" + xmlToCls, null);
              MappingObjectModelFactory.java: setter = parentCls.getMethod("set" + xmlToCls, new Class[]{getter.getReturnType()});
              MappingObjectModelFactory.java: Method getter = oCls.getMethod("get" + xmlToCls, null);
              MappingObjectModelFactory.java: setter = oCls.getMethod("set" + xmlToCls, new Class[]{getter.getReturnType()});
              MappingObjectModelProvider.java: String getterStr = Util.xmlNameToGetMethodName(localName, ignoreLowLine);
              MappingObjectModelProvider.java: getter = o.getClass().getMethod(getterStr, null);
              MappingObjectModelProvider.java: getter = o.getClass().getMethod(booleanGetterStr, null);
              metadata/unmarshalling/impl/AttributeBindingImpl.java: getter = parentClass.getMethod("get" + baseMethodName, null);
              metadata/unmarshalling/impl/AttributeBindingImpl.java: setter = parentClass.getMethod("set" + baseMethodName, new Class[]{getter.getReturnType()});
              metadata/unmarshalling/impl/DocumentBindingFactoryImpl.java: tmpGetter = parentType.getMethod("get" + baseMethodName, null);
              metadata/unmarshalling/impl/DocumentBindingFactoryImpl.java: tmpSetter = parentType.getMethod("set" + baseMethodName, new Class[]{tmpGetter.getReturnType()});
              metadata/unmarshalling/impl/DocumentBindingFactoryImpl.java: tmpGetter = parentType.getMethod("get" + baseMethodName, null);
              metadata/unmarshalling/impl/DocumentBindingFactoryImpl.java: tmpSetter = parentType.getMethod("set" + baseMethodName, new Class[]{tmpGetter.getReturnType()});
              metadata/unmarshalling/impl/RuntimeDocumentBinding.java: getter = parentType.getMethod("get" + baseMethodName, null);
              metadata/unmarshalling/impl/RuntimeDocumentBinding.java: setter = parentType.getMethod("set" + baseMethodName, new Class[]{getter.getReturnType()});
              metadata/unmarshalling/impl/XsdBinder.java: getter = parentType.getMethod("get" + elBasedClsName, null);
              metadata/unmarshalling/impl/XsdBinder.java: setter = parentType.getMethod("set" + elBasedClsName, new Class[]{getter.getReturnType()});
              metadata/marshalling/ObjectModelBindingFactory.java: getter = ownerClass.getMethod(getterName, null);
              metadata/AddMethodMetaData.java: public String getMethodName()
              ObjectModelBuilder.java: static Method getMethodForElement(Object factory, String name, Class[] params)
              ObjectModelBuilder.java: method = factory.getClass().getMethod(name, params);
              SchemalessMarshaller.java: Method[] methods = aClass.getMethods();
              SchemalessObjectModelFactory.java: Method getter = parent.getClass().getMethod("get" + localName, null);
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: Util.xmlNameToGetMethodName(elementName.getLocalPart(), term.getSchema().isIgnoreLowLine()) :
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: Method getter = parentClass.getMethod(getterName, null);
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: getValueMethod = o.getClass().getMethod(getValueMethodName, null);
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: o.getClass().getMethod(setValueMethodName, new Class[]{getValueMethod.getReturnType()});
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: private static Method getSetMethod(Class cls, String getMethodName, String setMethodName)
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: getKeyMethod = cls.getMethod(getMethodName, null);
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: throw new JBossXBRuntimeException("Method " + getMethodName + " not found in " + cls);
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: setKeyMethod = cls.getMethod(setMethodName, new Class[]{getKeyMethod.getReturnType()});
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: addMethodMetaData.getMethodName() +
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: addMethodMetaData.getMethodName() +
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: addMethod = ownerClass.getMethod(addMethodMetaData.getMethodName(), new Class[]{valueType});
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: addMethodMetaData.getMethodName() +
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: addMethodMetaData.getMethodName() +
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: keyMethod = oClass.getMethod(getKeyMethodName, null);
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: putMethod = ownerClass.getMethod(putMethodName, new Class[]{keyType, valueType});
              sunday/unmarshalling/impl/runtime/RtElementHandler.java: valueMethod = oClass.getMethod(valueMethodName, null);
              sunday/unmarshalling/impl/runtime/RtUtil.java: getter = cls.getMethod("get" + methodBase, null);
              sunday/unmarshalling/impl/runtime/RtUtil.java: getter = cls.getMethod("is" + methodBase, null);
              sunday/unmarshalling/impl/runtime/RtUtil.java: setter = cls.getMethod("set" + methodBase, new Class[]{fieldType});
              sunday/unmarshalling/impl/runtime/RtUtil.java: Method getter = cls.getMethod("get" + methodBase, null);
              sunday/unmarshalling/impl/runtime/RtUtil.java: setter = cls.getMethod("set" + methodBase, new Class[]{getter.getReturnType()});
              sunday/unmarshalling/impl/runtime/RtCharactersHandler.java: method = cls.getMethod(methodName, new Class[]{String.class, NamespaceContext.class});
              sunday/unmarshalling/XsdBinder.java: addMethodMetaData.getMethodName() + ", valueType=" + addMethodMetaData.getValueType()
              sunday/unmarshalling/XsdBinder.java: addMethodMetaData.getMethodName() +
              Util.java: public static String xmlNameToGetMethodName(String name, boolean ignoreLowLine)
              



              • 4. Re: Some profiling numbers

                 

                Load reflection model on demand? Think that would help?


                Yes, that is what we discussed before in some AOP thread.
                It should load the reflection objects lazily on demand.

                In a similar discussion on the dev-list I also said that everybody creating
                their own reflection cache is both a waste of time and memory.
                e.g. How many places do you think store primitive -> primitive.class
                in the codebase?

                • 5. Re: Some profiling numbers
                  bill.burke

                   

                  "scott.stark@jboss.org" wrote:
                  This seems like a microbenchmark. Why do you think these number are significant?


                  I don't think these are insignificant. One of the things we're pushing is that EJB3 can be unit tested. My little program I benched took 3.8 seconds to run of which 97% was bootstrapping.

                  • 6. Re: Some profiling numbers
                    bill.burke

                     

                    "adrian@jboss.org" wrote:
                    Load reflection model on demand? Think that would help?


                    Yes, that is what we discussed before in some AOP thread.
                    It should load the reflection objects lazily on demand.

                    In a similar discussion on the dev-list I also said that everybody creating
                    their own reflection cache is both a waste of time and memory.
                    e.g. How many places do you think store primitive -> primitive.class
                    in the codebase?


                    I still don't like the idea of writing wrappers around metadata that already exists in the VM, but maybe a cache and lazy loading will do the trick.

                    • 7. Re: Some profiling numbers

                      If the VM did it itself, there wouldn't be a problem (and caching reflection objects wouldn't
                      produce the performance gain that we see).

                      • 8. Re: Some profiling numbers

                         

                        "adrian@jboss.org" wrote:
                        If the VM did it itself, there wouldn't be a problem (and caching reflection objects wouldn't
                        produce the performance gain that we see).


                        But that's still no excuse for a crappy implementation that ends up caching
                        all possibly reachable reflection objects :-)

                        • 9. Re: Some profiling numbers

                          I've done a simple fix that stops it leaking across the entire space
                          via class references. This still needs completing for other objects, but I doubt that
                          will have the same impact.

                          • 10. Re: Some profiling numbers

                            This might also reduce the Logger.getLogger() calls as it will statically initializing
                            less classes?

                            • 11. Re: Some profiling numbers
                              aloubyansky

                               

                              "adrian@jboss.org" wrote:
                              Getting JBossXB to use the same reflection model/cache would also
                              remove some duplicate/inefficent work


                              Definitely, reflection and introspection is used in a heavy and dirty way there.