Startup time ~50% slower with Hibernate 3

Darren_Jones · **Joined:** Thu Aug 28, 2003 6:03 am **Posts:** 7

We have a desktop application that has just over 100 mapped classes (one class per mapping file). When we upgraded to Hibernate 3 the startup time of the application increased to 19 seconds (previously 13 seconds with Hibernate 2). I have changed all of the mapping files to reference the Hibernate 3 DTD as mentioned in a different post.

The increase was all in the creation of the Configuration, and the subsequent buildSessionFactory() call on it.

I have tried serializing the Configuration (new in Hibernate 3!) and this cuts the time down by one second and is still slower than Hibernate 2.1.6.

I'm not dissing Hibernate 3 (the new features will be very useful to us), but would be grateful if anyone could answer:

Has the startup code been looked at for rc1 with a view to fully optimizing it (i.e. is it as fast as it can be with all of the new mapping features), or will the performance be looked at for a future release?

Many thanks.

tpischke · **Posted:** Thu Mar 10, 2005 7:38 am

For comparison, Using the GenericDialect with the FirstSQL database, I'm seeing startup time jump from around 15s under HB2.1 to about 45s under HB3.

max · **Posted:** Thu Mar 10, 2005 7:56 am

afaik we havent introduced big performance hogs in the new configuration/sessionfactory build.

the only known caveat is to ensure you have the right DTD.

try to look at the log or even try running a profiler against your setup to see where the time is spent.

/max

tpischke · **Posted:** Thu Mar 10, 2005 8:11 am

Updated all DTDs to 3.0 and setup is lightning fast now. You guys rock.

You might want to make a quick note of this on the migration page. I tried to add a comment to the WIKI but it wouldn't let me log in to add a comment for some reason.

emmanuel · **Posted:** Thu Mar 10, 2005 9:04 am

done, thanks

Darren_Jones · **Joined:** Thu Aug 28, 2003 6:03 am **Posts:** 7

I'm still getting slower performance even with the hibernate3 DTD in my mapping files. I've done some profiling and come up with a major difference in the performance of the Configuration.buildSessionFactory() method. It looks like it's mostly down to a different usage of CGLIB - Hibernate 2 used CGLIB FastClass Objects, and Hibernate 3 seems to use CGLIB Enhancer Objects.

I've included the most important (I think!) sequences of method calls here.

It doesn't mean much to me (I know very little about the CGLIB internals). But does this explain the slowdown I'm experiencing? Can anything be done to overcome this?

Thanks,

Darren.

Code:

Hibernate 2
===========

34.83% - 12148 ms - 1 inv. - net.sf.hibernate.cfg.Configuration.buildSessionFactory()
  30.98% - 10808 ms - 1 inv. - net.sf.hibernate.impl.SessionFactoryImpl.net.sf.hibernate.impl.SessionFactoryImpl()
    28.46% - 9928 ms - 113 inv. - net.sf.hibernate.persister.PersisterFactory.createClassPersister()
      24.94% - 8700 ms - 107 inv. - net.sf.hibernate.persister.EntityPersister.net.sf.hibernate.persister.EntityPersister()
        23.98% - 8364 ms - 107 inv. - net.sf.hibernate.persister.AbstractEntityPersister.net.sf.hibernate.persister.AbstractEntityPersister()
          13.01% - 4540 ms - 107 inv. - net.sf.hibernate.util.ReflectHelper.getFastClass()
            13.01% - 4540 ms - 107 inv. - net.sf.cglib.reflect.FastClass.create()
              13.01% - 4540 ms - 107 inv. - net.sf.cglib.reflect.FastClass.create()
                13.01% - 4540 ms - 107 inv. - net.sf.cglib.reflect.FastClass$Generator.create()
                  13.01% - 4540 ms - 107 inv. - net.sf.cglib.core.AbstractClassGenerator.create()
                    10.68% - 3728 ms - 107 inv. - net.sf.cglib.core.DefaultGeneratorStrategy.generate()
                      10.55% - 3680 ms - 107 inv. - net.sf.cglib.reflect.FastClass$Generator.generateClass()
                        10.52% - 3672 ms - 107 inv. - net.sf.cglib.reflect.FastClassEmitter.net.sf.cglib.reflect.FastClassEmitter()
                          4.93% - 1720 ms - 107 inv. - net.sf.cglib.reflect.FastClassEmitter.emitIndexByClassArray()
                          2.86% - 1000 ms - 214 inv. - net.sf.cglib.reflect.FastClassEmitter.invokeSwitchHelper()
                          1.76% - 616 ms - 107 inv. - net.sf.cglib.reflect.FastClassEmitter.emitIndexBySignature()
                          ...
          7.32% - 2556 ms - 19 inv. - net.sf.hibernate.proxy.CGLIBProxyFactory.postInstantiate()
          1.85% - 648 ms - 107 inv. - net.sf.hibernate.util.ReflectHelper.getBulkBean()

Hibernate 3
===========

Profiler output for thread main . application idbs.impl.keystone.launch.Launcher (CPU profiler output - Instrumentation / Methods)
----------------------------------------------------------------------------------------------------------------------------------

52.4% - 30016 ms - 1 inv. - org.hibernate.cfg.Configuration.buildSessionFactory()
  47.88% - 27428 ms - 1 inv. - org.hibernate.impl.SessionFactoryImpl.org.hibernate.impl.SessionFactoryImpl()
    46.03% - 26368 ms - 113 inv. - org.hibernate.persister.PersisterFactory.createClassPersister()
      43.55% - 24944 ms - 107 inv. - org.hibernate.persister.entity.SingleTableEntityPersister.org.hibernate.persister.entity.SingleTableEntityPersister()
        42.29% - 24224 ms - 107 inv. - org.hibernate.persister.entity.BasicEntityPersister.org.hibernate.persister.entity.BasicEntityPersister()
          41.81% - 23948 ms - 107 inv. - org.hibernate.tuple.EntityMetamodel.org.hibernate.tuple.EntityMetamodel()
            41.07% - 23528 ms - 107 inv. - org.hibernate.tuple.TuplizerLookup.create()
              40.79% - 23368 ms - 107 inv. - org.hibernate.tuple.PojoTuplizer.org.hibernate.tuple.PojoTuplizer()
                38.82% - 22236 ms - 107 inv. - org.hibernate.tuple.AbstractTuplizer.org.hibernate.tuple.AbstractTuplizer()
                  38.04% - 21788 ms - 107 inv. - org.hibernate.tuple.PojoTuplizer.buildProxyFactory()
                    37.96% - 21744 ms - 107 inv. - org.hibernate.proxy.CGLIBProxyFactory.postInstantiate()
                      37.92% - 21720 ms - 107 inv. - org.hibernate.proxy.CGLIBLazyInitializer.getProxyFactory()
                        37.85% - 21684 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.create()
                          37.85% - 21684 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.create()
                            37.85% - 21684 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.createHelper()
                              37.78% - 21644 ms - 107 inv. - net.sf.cglib.core.AbstractClassGenerator.create()
                                23.97% - 13732 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.firstInstance()
                                12.37% - 7088 ms - 107 inv. - net.sf.cglib.core.DefaultGeneratorStrategy.generate()
                                  11.96% - 6852 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.generateClass()
                                    11.13% - 6380 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.emit()
                                      10.43% - 5976 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.emitMethods()
                                        6.81% - 3904 ms - 107 inv. - net.sf.cglib.proxy.MethodInterceptorGenerator.generate()
                                        3.38% - 1936 ms - 107 inv. - net.sf.cglib.proxy.MethodInterceptorGenerator.generateStatic()
                                        ...
                                                                                                                                                                                                     52.4% - 30016 ms - 1 inv. - org.hibernate.cfg.Configuration.buildSessionFactory()
                                                                                                                                                                                                        47.88% - 27428 ms - 1 inv. - org.hibernate.impl.SessionFactoryImpl.org.hibernate.impl.SessionFactoryImpl()
                                                                                                                                                                                                           46.03% - 26368 ms - 113 inv. - org.hibernate.persister.PersisterFactory.createClassPersister()
                                                                                                                                                                                                              43.55% - 24944 ms - 107 inv. - org.hibernate.persister.entity.SingleTableEntityPersister.org.hibernate.persister.entity.SingleTableEntityPersister()
                                                                                                                                                                                                                 42.29% - 24224 ms - 107 inv. - org.hibernate.persister.entity.BasicEntityPersister.org.hibernate.persister.entity.BasicEntityPersister()
                                                                                                                                                                                                                    41.81% - 23948 ms - 107 inv. - org.hibernate.tuple.EntityMetamodel.org.hibernate.tuple.EntityMetamodel()
                                                                                                                                                                                                                       41.07% - 23528 ms - 107 inv. - org.hibernate.tuple.TuplizerLookup.create()
                                                                                                                                                                                                                          40.79% - 23368 ms - 107 inv. - org.hibernate.tuple.PojoTuplizer.org.hibernate.tuple.PojoTuplizer()
                                                                                                                                                                                                                             38.82% - 22236 ms - 107 inv. - org.hibernate.tuple.AbstractTuplizer.org.hibernate.tuple.AbstractTuplizer()
                                                                                                                                                                                                                                38.04% - 21788 ms - 107 inv. - org.hibernate.tuple.PojoTuplizer.buildProxyFactory()
                                                                                                                                                                                                                                   37.96% - 21744 ms - 107 inv. - org.hibernate.proxy.CGLIBProxyFactory.postInstantiate()
                                                                                                                                                                                                                                      37.92% - 21720 ms - 107 inv. - org.hibernate.proxy.CGLIBLazyInitializer.getProxyFactory()
                                                                                                                                                                                                                                         37.85% - 21684 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.create()
                                                                                                                                                                                                                                            37.85% - 21684 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.create()
                                                                                                                                                                                                                                               37.85% - 21684 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.createHelper()
                                                                                                                                                                                                                                                  37.78% - 21644 ms - 107 inv. - net.sf.cglib.core.AbstractClassGenerator.create()
                                                                                                                                                                                                                                                     23.97% - 13732 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.firstInstance()
                                                                                                                                                                                                                                                     12.37% - 7088 ms - 107 inv. - net.sf.cglib.core.DefaultGeneratorStrategy.generate()
                                                                                                                                                                                                                                                        11.96% - 6852 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.generateClass()
                                                                                                                                                                                                                                                           11.13% - 6380 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.emit()
                                                                                                                                                                                                                                                              10.43% - 5976 ms - 107 inv. - net.sf.cglib.proxy.Enhancer.emitMethods()
                                                                                                                                                                                                                                                                 6.81% - 3904 ms - 107 inv. - net.sf.cglib.proxy.MethodInterceptorGenerator.generate()
                                                                                                                                                                                                                                                                 3.38% - 1936 ms - 107 inv. - net.sf.cglib.proxy.MethodInterceptorGenerator.generateStatic()

Darren_Jones · **Joined:** Thu Aug 28, 2003 6:03 am **Posts:** 7

Whoops - apologies - in the previous message, ignore everything after the ... in the Hibernate 3 section.

max · **Posted:** Thu Mar 10, 2005 1:25 pm

AFAIK what you see is also what took most time in H2 - namely class loading triggered by cglib enhancement.

i'll revisit this at some time.
If you have a runnable test case that is remarkably faster in H2 and slower in H3 it would really help!

-max

Darren_Jones · **Joined:** Thu Aug 28, 2003 6:03 am **Posts:** 7

I'll try to get some test mappings together. It may take some time to get enough classes together!