sounds good with this improvement! Will test it on our unit test and verify its effect.

Baliukas, how old is the vms you say that will be slower by this change ?
And is the slowness only on startup or does it also affet the proxy invocation ?

It slows proxy instance creation, "Class.newInstance" it slow on 1.3 (native method invocation and security checks), but since 1.4.x it is similar to cglib (byte code generation) to avoid native methods for "small" code. Reflection optimizations without security manager do not make sence since 1.4, cglib is bit faster (it takes special use cases like "copy" into account ), but it wastes memory.

I have tried to run standalone test using profiler, it shows "ClassLoder.defineClass" (%7) and "DefaultNamingPolicy" (%7) are hotspots. Naming policy is pluggable, but probably it doe's not make sence to customize it to save 5 - 6 % (the weight will be less with all stuff).

Hi,

I moved from 2.1.8 to 3.0.5 and now trying to use addCacheableFile(File). I replaced
... new Configuration().configure(config).buildSessionFactory();

with
... new Configuration().addCacheableFile(config).buildSessionFactory();


and startup now fails with the following output if the serialized config file does not exist:

2005-05-31 19:51:44,094 [main] INFO org.hibernate.cfg.Environment - Hibernate 3.0.5
2005-05-31 19:51:44,094 [main] INFO org.hibernate.cfg.Environment - hibernate.properties not found
2005-05-31 19:51:44,094 [main] INFO org.hibernate.cfg.Environment - using CGLIB reflection optimizer
2005-05-31 19:51:44,094 [main] INFO org.hibernate.cfg.Environment - using JDK 1.4 java.sql.Timestamp handling
2005-05-31 19:51:44,266 [main] DEBUG org.hibernate.util.DTDEntityResolver - trying to locate http://hibernate.sourceforge.net/hibern ... on-3.0.dtd in classpath under org/hibernate/
2005-05-31 19:51:44,266 [main] DEBUG org.hibernate.util.DTDEntityResolver - found http://hibernate.sourceforge.net/hibern ... on-3.0.dtd in classpath
2005-05-31 19:51:44,313 [main] INFO org.hibernate.cfg.Configuration - Writing cached file of hibernate.cfg.xml to [...]\hibernate.cfg.xml.bin
2005-05-31 19:51:44,313 [main] DEBUG org.hibernate.util.SerializationHelper - Starting serialization of object [org.dom4j.tree.DefaultDocument@1f3aa07 [Document: name file:///[...]/hibernate.cfg.xml]]
2005-05-31 19:51:44,437 [main] DEBUG org.hibernate.cfg.Configuration - Preparing to build session factory with filters : {}
2005-05-31 19:51:44,437 [main] INFO org.hibernate.cfg.Configuration - processing extends queue
2005-05-31 19:51:44,437 [main] INFO org.hibernate.cfg.Configuration - processing collection mappings
2005-05-31 19:51:44,437 [main] INFO org.hibernate.cfg.Configuration - processing association property references
2005-05-31 19:51:44,453 [main] INFO org.hibernate.cfg.Configuration - processing foreign key constraints
2005-05-31 19:51:44,453 [main] WARN org.hibernate.connection.UserSuppliedConnectionProvider - No connection properties specified - the user must supply JDBC connections
2005-05-31 19:51:44,469 [main] FATAL de.robolab.kpsi.cutting.CuttingApplication - database product name cannot be null
org.hibernate.HibernateException: database product name cannot be null
at org.hibernate.dialect.DialectFactory.determineDialect(DialectFactory.java:57)
at org.hibernate.dialect.DialectFactory.buildDialect(DialectFactory.java:39)
at org.hibernate.cfg.SettingsFactory.determineDialect(SettingsFactory.java:374)
at org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:110)
at org.hibernate.cfg.Configuration.buildSettings(Configuration.java:1463)
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1004)
at de.robolab.kpsi.common.hibernate.HibernateUtils.buildSessionFactory(HibernateUtils.java:58)
at de.robolab.kpsi.common.hibernate.HibernateUtils.init(HibernateUtils.java:52)
at de.robolab.kpsi.common.hibernate.HibernateApplication.init(HibernateApplication.java:31)
at de.robolab.kpsi.cutting.CuttingApplication.init(CuttingApplication.java:57)
at de.robolab.kpsi.cutting.CuttingApplication.main(CuttingApplication.java:47)




The *bin file is created anyway and when starting again the output is:


2005-05-31 19:49:13,672 [main] INFO org.hibernate.cfg.Environment - Hibernate 3.0.5
2005-05-31 19:49:13,672 [main] INFO org.hibernate.cfg.Environment - hibernate.properties not found
2005-05-31 19:49:13,672 [main] INFO org.hibernate.cfg.Environment - using CGLIB reflection optimizer
2005-05-31 19:49:13,687 [main] INFO org.hibernate.cfg.Environment - using JDK 1.4 java.sql.Timestamp handling
2005-05-31 19:49:13,750 [main] INFO org.hibernate.cfg.Configuration - Mapping cached file: [...]\hibernate.cfg.xml.bin
2005-05-31 19:49:13,750 [main] DEBUG org.hibernate.util.SerializationHelper - Starting deserialization of object
2005-05-31 19:49:13,750 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.DefaultDocument]
2005-05-31 19:49:13,750 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:13,750 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.AbstractDocument]
2005-05-31 19:49:13,750 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:13,750 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.AbstractBranch]
2005-05-31 19:49:13,750 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:13,750 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.AbstractNode]
2005-05-31 19:49:13,750 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:13,812 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [java.util.ArrayList]
2005-05-31 19:49:13,812 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:13,812 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.DefaultElement]
2005-05-31 19:49:13,812 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:13,812 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.AbstractElement]
2005-05-31 19:49:13,812 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:13,906 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.DefaultAttribute]
2005-05-31 19:49:13,922 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:13,922 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.FlyweightAttribute]
2005-05-31 19:49:13,922 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:13,922 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.AbstractAttribute]
2005-05-31 19:49:13,922 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,015 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.QName]
2005-05-31 19:49:14,015 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,062 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.DocumentFactory]
2005-05-31 19:49:14,062 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,187 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.DefaultText]
2005-05-31 19:49:14,203 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,203 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.FlyweightText]
2005-05-31 19:49:14,203 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,203 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.AbstractText]
2005-05-31 19:49:14,203 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,203 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.AbstractCharacterData]
2005-05-31 19:49:14,203 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,281 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.DefaultComment]
2005-05-31 19:49:14,297 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,297 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.FlyweightComment]
2005-05-31 19:49:14,297 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,297 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.AbstractComment]
2005-05-31 19:49:14,297 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,422 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.DefaultDocumentType]
2005-05-31 19:49:14,437 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,437 [main] DEBUG org.hibernate.util.SerializationHelper - Attempting to locate class [org.dom4j.tree.AbstractDocumentType]
2005-05-31 19:49:14,437 [main] DEBUG org.hibernate.util.SerializationHelper - Class resolved through context class loader
2005-05-31 19:49:14,484 [main] DEBUG org.hibernate.cfg.Configuration - Preparing to build session factory with filters : {}
2005-05-31 19:49:14,484 [main] INFO org.hibernate.cfg.Configuration - processing extends queue
2005-05-31 19:49:14,484 [main] INFO org.hibernate.cfg.Configuration - processing collection mappings
2005-05-31 19:49:14,484 [main] INFO org.hibernate.cfg.Configuration - processing association property references
2005-05-31 19:49:14,484 [main] INFO org.hibernate.cfg.Configuration - processing foreign key constraints
2005-05-31 19:49:14,500 [main] WARN org.hibernate.connection.UserSuppliedConnectionProvider - No connection properties specified - the user must supply JDBC connections
2005-05-31 19:49:14,500 [main] FATAL de.robolab.kpsi.cutting.CuttingApplication - database product name cannot be null
org.hibernate.HibernateException: database product name cannot be null
at org.hibernate.dialect.DialectFactory.determineDialect(DialectFactory.java:57)
at org.hibernate.dialect.DialectFactory.buildDialect(DialectFactory.java:39)
at org.hibernate.cfg.SettingsFactory.determineDialect(SettingsFactory.java:374)
at org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:110)
at org.hibernate.cfg.Configuration.buildSettings(Configuration.java:1463)
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1004)
at de.robolab.kpsi.common.hibernate.HibernateUtils.buildSessionFactory(HibernateUtils.java:58)
at de.robolab.kpsi.common.hibernate.HibernateUtils.init(HibernateUtils.java:52)
at de.robolab.kpsi.common.hibernate.HibernateApplication.init(HibernateApplication.java:31)
at de.robolab.kpsi.cutting.CuttingApplication.init(CuttingApplication.java:57)
at de.robolab.kpsi.cutting.CuttingApplication.main(CuttingApplication.java:47)





Can anyone tell me what's wrong?
Thanks
Sebastian

You must specify a Hibernate Dialect.

Thank you for the quick reply!

I found my mistake. All the time I thought, that the hibernate.cfg.xml file should be serialized and I passed this config file to addCacheableFile(). So there where no config infos in the Configuration.properties.
Now I remembered that with the Configuration#add*() methods one can only add mapping files and not the whole configuration. I had my mapping resources in the hibernate.cfg.xml all the time so I forgot!
Moving each mapping resource from hibernate.cfg.xml to addCacheableFile() was successful.

Regards
Sebastian

BTW "2005-05-31 19:49:13,672 [main] INFO org.hibernate.cfg.Environment - using CGLIB reflection optimizer "

It does many reflection related stuff and generates code on stratup too, you can try to dissable it.

Startup time is a big issue for us (test suites, context reloads etc) so I was eager to apply baliukas's patch HHH-525 and run a few informal tests. Results are below.

I agree with bonnyr: for large models, in my experience the serialization of the XML configuration helps but it is not significant compared to the time spent in buildSessionFactory().


My test setup

-Pentium 4 2.8Ghz
-Linux 2.6.10-1.766_FC3smp
-Sun JVM 1.5.0_01-b08
-168 persistent classes
-hibernate.show_sql true
-hibernate.cglib.use_reflection_optimizer false

Test results

3.0.1

Configuration.addCacheableFile() elapsed ms=1622
Configuration.configure().buildSessionFactory() elapsed ms=22858
Configuration.addCacheableFile() elapsed ms=1500
Configuration.configure().buildSessionFactory() elapsed ms=23940
Configuration.addCacheableFile() elapsed ms=1278
Configuration.configure().buildSessionFactory() elapsed ms=31674
Configuration.addCacheableFile() elapsed ms=1047
Configuration.configure().buildSessionFactory() elapsed ms=21361

3.0.5

Configuration.addCacheableFile() elapsed ms=2040
Configuration.configure().buildSessionFactory() elapsed ms=23078
Configuration.addCacheableFile() elapsed ms=2450
Configuration.configure().buildSessionFactory() elapsed ms=27872
Configuration.addCacheableFile() elapsed ms=1425
Configuration.configure().buildSessionFactory() elapsed ms=18868
Configuration.addCacheableFile() elapsed ms=1020
Configuration.configure().buildSessionFactory() elapsed ms=19650
Configuration.addCacheableFile() elapsed ms=874
Configuration.configure().buildSessionFactory() elapsed ms=20940


3.0.5 patched

Configuration.addCacheableFile() elapsed ms=1919
Configuration.configure().buildSessionFactory() elapsed ms=14059
Configuration.addCacheableFile() elapsed ms=902
Configuration.configure().buildSessionFactory() elapsed ms=12704
Configuration.addCacheableFile() elapsed ms=860
Configuration.configure().buildSessionFactory() elapsed ms=14584
Configuration.addCacheableFile() elapsed ms=955
Configuration.configure().buildSessionFactory() elapsed ms=14827

Conclusion

The patch seems to cut overall time spent in buildSessionFactory() from 25s to 14s. I have not noticed any adverse effect on performance after the factory has been built.

I will be using this patch going forward. Thanks Baliukas!

Ben

Hi,

I have a similar problem..

Recently moved to Hibernate 3.0.5. I am facing serious startup time issue with weblogic server.

I have around 800 mapping files configured under a single hibernate.cfg.xml. The build session factory is taking around 30-35 seconds in JBoss where as the same ear deployed on weblogic 8.1 is taking close to 5 minutes. (the behaviour is consistent) I added antlr jar on the weblogic pre-classpath to integrate hibernate 3 with Weblogic.

Pls share your thoughts on this.

Best Regards
Rajesh

Rajesh,

so ditch Weblogic and move to JBoss ;)

seriously, have you tried patch 525? Does it make a big difference?

What about moving your 800 class mappings into a single file and calling addCacheableFile() instead of having to open 800 separate files on the filesystem and parse each one?

Ben

ok guys,

I have also verified that this patch reduces build of a SF by half.
That's pretty nice ;)

Monitor the HHH-525 for when I have committed it (first after testing if it has any sideeffects)

cool.

Max, for large models (100s of classes), do you have any experience of the performance differences between "hbm file per class" and "single hbm file" strategies? Presume it depends on how interconnected the model is?

Apart from the potential performance problems of having to seek and open/parse/close literally hundreds of XML files on the file system instead of just one, we much prefer the single file approach anyway as it fits in better with our fully GUI generated solution, makes source control easier, makes it easier to manage default settings etc etc.

Ben

I don't think 1 vs 100 .xml files affect performance besides the extra xml parsing (which can be avoided via addCachableFile).

Hi,

I applied the HHH-525 and it reduces the time for building the session factory from 35 to 25(good improvement) However in weblogic, it is still logging 3-4 minutes for loading the session factory.

I did a profiling with YourKit and found that most of the time is consumed by org.hibernate.util.classForName(String) and inside that weblogic.utils.classloaders.GenericClassLoader and java.lang.Class.forName

Any thoughts ?

Pls dont say JBoss ;)

Regards
Rajesh

sounds like weblogic has a bad performant classloader ? weird.

This is most likely because your database server sits on a remote location (number of round trips I suppose).
I'm experiencing 12 sec hibernate startup times vs 3 seconds when mysql is on another machine.

Bruno