Migration from Hibernate 3 to 4 slows down startup

Question

we are trying to migrate our project from hibernate 3 to hibernate 4. Everything is working fine, but the problem is the startup.

We do not use JPA, we use direct hibernate with the xml file and mapping files.

 <?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-configuration PUBLIC
        "-//Hibernate/Hibernate Configuration DTD 3.0//EN"
        "http://hibernate.org/dtd/hibernate-configuration-3.0.dtd">
<hibernate-configuration>
    <session-factory>

        <property name="hibernate.connection.driver_class">com.informix.jdbc.IfxDriver</property>
        <property name="hibernate.connection.url">jdbc:informix-sqli://xxx:xxx/xxx:INFORMIXSERVER=xxx</property>
        <property name="hibernate.connection.username">xxx</property>
        <property name="hibernate.connection.password">xxx</property>
        <property name="hibernate.dialect">org.hibernate.dialect.InformixDialect</property>
        <property name="hibernate.format_sql">true</property>
        <property name="hibernate.show_sql">false</property>        


        <property name="generated.mappingFile">dev.xml</property>
   </session-factory>
</hibernate-configuration>

The property generated.mappingFile is an own property. On startup the file will be loaded (dev.xml). This file looks like this:

        <mapping resource="de/cargosoft/edi/cargoservice/entities/aart/Aart_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/abteilung/Abteilung_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/adr/Adr_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/adraesort/Adraesort_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/adrakte/Adrakte_DEV.hbm.xml" />
        ...
        <mapping resource="de/cargosoft/edi/cargoservice/entities/zollanmtxt/Zollanmtxt_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/sstbasis/Sstbasis_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/sststruktur/Sststruktur_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/ssthandler/Ssthandler_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/sstproperty/Sstproperty_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/sstprophandler/Sstprophandler_DEV.hbm.xml" />
        <mapping resource="de/cargosoft/edi/cargoservice/entities/sstneustart/Sstneustart_DEV.hbm.xml" />

We reduced the number of mapping in this post. we do have more then 500 mappings in the moment.

With hibernate 3 it took 2 seconds to load all mappings. With hibernate 4 it takes over 2 minutes.

Here is the log file from hibernate 3.2.GA:

     07:36:21,293 INFO  [HibernateManager              ] | Verwende Mapping-Collection Datei : /com/cargosoft/csedi/data/mappings_dev.xml
     07:36:21,347 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/aart/Aart_DEV.hbm.xml
     07:36:21,443 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/abteilung/Abteilung_DEV.hbm.xml
     07:36:21,458 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/adr/Adr_DEV.hbm.xml
     07:36:21,495 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/adraesort/Adraesort_DEV.hbm.xml
     07:36:21,523 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/adrakte/Adrakte_DEV.hbm.xml
     ...
     07:36:23,475 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/zollanmtxt/Zollanmtxt_DEV.hbm.xml
     07:36:23,477 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/sstbasis/Sstbasis_DEV.hbm.xml
     07:36:23,479 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/sststruktur/Sststruktur_DEV.hbm.xml
     07:36:23,481 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/ssthandler/Ssthandler_DEV.hbm.xml
     07:36:23,482 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/sstproperty/Sstproperty_DEV.hbm.xml
     07:36:23,484 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/sstprophandler/Sstprophandler_DEV.hbm.xml
     07:36:23,486 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  com/cargosoft/csedi/data/sstneustart/Sstneustart_DEV.hbm.xml
     07:36:23,488 INFO  [HibernateManager              ] | Create new SessionFactory for: jdbc:informix-sqli://...

With hibernate 4.3.8-Final:

     07:38:04,749 INFO  [HibernateManager              ] | Verwende Mapping-Collection Datei : /de/cargosoft/edi/cargoservice/entities/mappings_dev.xml
     07:38:04,824 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/aart/Aart_DEV.hbm.xml
     07:38:05,249 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/abteilung/Abteilung_DEV.hbm.xml
     07:38:05,527 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/adr/Adr_DEV.hbm.xml
     07:38:05,792 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/adraesort/Adraesort_DEV.hbm.xml
     07:38:06,077 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/adrakte/Adrakte_DEV.hbm.xml
     ...
     07:40:14,119 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/zollanmtxt/Zollanmtxt_DEV.hbm.xml
     07:40:14,499 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/sstbasis/Sstbasis_DEV.hbm.xml
     07:40:14,746 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/sststruktur/Sststruktur_DEV.hbm.xml
     07:40:14,972 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/ssthandler/Ssthandler_DEV.hbm.xml
     07:40:15,211 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/sstproperty/Sstproperty_DEV.hbm.xml
     07:40:15,434 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/sstprophandler/Sstprophandler_DEV.hbm.xml
     07:40:15,657 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/sstneustart/Sstneustart_DEV.hbm.xml
     07:40:15,878 INFO  [HibernateManager              ] | Create new SessionFactory for: jdbc:informix-sqli://...

The method which adds the mapping files look like this:

 for (Node node : nodes) {
      Element element = (Element) node;
      String resource = element.attributeValue("resource");
      logger.info("Adding this resource to hibernate now          :  " + resource);
      configuration.addResource(resource);
 }

The time lack is on addResource.

We also tried it by moving the mapping element directly to the hibernate.cfg.xml file but it takes the same time to startup.

We believe hibernate is validating something what hibernate 3 did not.

Has anyone an idea to fix this issue? We can not wait 2 minutes for each test run.

Thanks a lot and many greetings, Hauke

UPDATE

I changed the loglevel to "DEBUG" and now it comes this:

I changed to loglevel to debug and this is coming out now:

  11:29:22,781 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/aart/Aart_DEV.hbm.xml
  11:29:22,782 INFO  [Configuration                 ] | HHH000221: Reading mappings from resource: de/cargosoft/edi/cargoservice/entities/aart/Aart_DEV.hbm.xml
  11:29:22,804 DEBUG [DTDEntityResolver             ] | Trying to resolve system-id [http://hibernate.org/dtd/hibernate-mapping-3.0.dtd]
  11:29:23,149 INFO  [HibernateManager              ] | Adding this resource to hibernate now          :  de/cargosoft/edi/cargoservice/entities/abteilung/Abteilung_DEV.hbm.xml
  ...

So it seems that the DTDEntityResolver takes about 200ms - 400ms for each entity. With 500 entities this will sum up.

So the question is, how to disable that?

Answer 1

You need to change the DTD of all your HBM configuration files from:

http://hibernate.org/dtd/hibernate-mapping-3.0.dtd

to:

http://www.hibernate.org/dtd/hibernate-mapping-3.0.dtd

This is how the DTDEntityResolver tries to locate the DTO:

public class DTDEntityResolver implements EntityResolver, Serializable {

    private static final String HIBERNATE_NAMESPACE = "http://www.hibernate.org/dtd/";
    private static final String OLD_HIBERNATE_NAMESPACE = "http://hibernate.sourceforge.net/";
    private static final String USER_NAMESPACE = "classpath://";

    public InputSource resolveEntity(String publicId, String systemId) {
        InputSource source = null; // returning null triggers default behavior
        if ( systemId != null ) {
            LOG.debugf( "Trying to resolve system-id [%s]", systemId );
            if ( systemId.startsWith( HIBERNATE_NAMESPACE ) ) {
                LOG.debug( "Recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/" );
                source = resolveOnClassPath( publicId, systemId, HIBERNATE_NAMESPACE );
            }
            else if ( systemId.startsWith( OLD_HIBERNATE_NAMESPACE ) ) {
                LOG.recognizedObsoleteHibernateNamespace( OLD_HIBERNATE_NAMESPACE, HIBERNATE_NAMESPACE );
                LOG.debug( "Attempting to resolve on classpath under org/hibernate/" );
                source = resolveOnClassPath( publicId, systemId, OLD_HIBERNATE_NAMESPACE );
            }
            else if ( systemId.startsWith( USER_NAMESPACE ) ) {
                LOG.debug( "Recognized local namespace; attempting to resolve on classpath" );
                String path = systemId.substring( USER_NAMESPACE.length() );
                InputStream stream = resolveInLocalNamespace( path );
                if ( stream == null ) {
                    LOG.debugf( "Unable to locate [%s] on classpath", systemId );
                }
                else {
                    LOG.debugf( "Located [%s] in classpath", systemId );
                    source = new InputSource( stream );
                    source.setPublicId( publicId );
                    source.setSystemId( systemId );
                }
            }
        }
        return source;
    }

   ...

}

Hibernate can't locate the hibernate-mapping-3.0.dtd configuration file in the hibernate-core-4.3.8.Final.jar and so it goes recursevily through all your class-path, and since you have a huge project, that explains why it starts so slow.

Answer 2

I have once used a trick to skip the DTD validation when parsing XML files, using the below code. Your case is more complicated as you need to plug this into the Hibernate config parser. But it may get you started.

private boolean skipDtd = true; // TODO make configurable

private EntityResolver dummyDtdResolver = new EntityResolver()
{
    @Override
    public InputSource resolveEntity(String publicId, String systemId) throws SAXException, IOException
    {
        if (skipDtd && systemId.toLowerCase().endsWith(".dtd"))
            return new InputSource(new StringReader(""));
        return null;
    }
};

A few ways to use it:

1. From a DocumentBuilder

   DocumentBuilderFactory dbf = DocumentBuilderFactory.newInstance();
   DocumentBuilder parser = dbf.newDocumentBuilder();
   parser.setEntityResolver(dummyDtdResolver);
   ...
   parser.parse(new File(xmlName));        
   

2. From an XmlReader

   SAXParserFactory saxParserFactory = SAXParserFactory.newInstance();
   saxParserFactory.setNamespaceAware(true);
   XMLReader xmlReader = saxParserFactory.newSAXParser().getXMLReader();
   xmlReader.setEntityResolver(dummyDtdResolver);
   ...
   new SAXSource(xmlReader, inputSource);