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

    Some profiling numbers

    Bill Burke Master

      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
          Scott Stark Master

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

          • 3. Re: Some profiling numbers
            Adrian Brock Master

            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
              Adrian Brock Master

               

              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 Master

                 

                "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 Master

                   

                  "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
                    Adrian Brock Master

                    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 Brock Master

                       

                      "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
                        Adrian Brock Master

                        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
                          Adrian Brock Master

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

                          • 11. Re: Some profiling numbers
                            Alexey Loubyansky Master

                             

                            "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.