Just *referencing* a connection is slow?

calle · **Joined:** Tue Sep 02, 2003 8:19 pm **Posts:** 19

Hi,

I'm having serious performance issues with my collections - and the only part of it I care about now is read access. Here's what happens.

I have a persistent class that contains a tree of also persistent entries. Mapping is this:

Poll:
...
<list
name="questions"
lazy="true"
cascade="all-delete-orphan"
>
<key column="pollId"/>
<index column="pollIndex"/>
<one-to-many class="de...Question"/>
</list>
...

Poll has the following methods that are of interest now:
public Iterator iterateQuestions()
{
return this.getQuestions().iterator();
}
protected List getQuestions()
{
if (questions == null)
{
this.setQuestions(new ArrayList());
}

return questions;
}

Poll has a proxy. Now, when I run this part of my application, I load a Poll instance and initialize() it, so now it shouldn't need any more db access or other costly things, right?

This is the code I'm executing:

log.debug("Initializing UserResponse with poll");
Iterator i = p.iterateQuestions();
Question q;
log.debug("entering question loop");
while (i.hasNext())
{
...doing some things with the question...

In the logs I get this:

22:19:09,069 DEBUG UserResponse:637 - Initializing UserResponse with poll
22:19:12,015 DEBUG UserResponse:641 - entering question loop

It takes almost *three* seconds just to get the question iterator? Later on down the tree (questions also contain nested sets of answers), there are other slow parts, but this is the weirdest. I can't believe this. My previous experiences with Hibernate never showed behavior like this, so I'm currently thinking I must be doing something wrong. But what? I have checked all kinds of things, but haven't found anything yet. I checked server load, it is not idling, but the slowness of this part is way out of proportion when compared with anything else happening in the VM.

I'm running on an AthlonXP 1600 box, 300mb of ram for the VM, Debian Woody with 2.4.20 kernel, Java HotSpot(TM) Client VM (build Blackdown-1.3.1_02b-FCS, mixed mode), Tomcat4.0.4, Struts 1.1 and Hibernate 2.0.3. The database is a PostgreSQL 7.2 on the same box.

Please let me know if you have any idea what might be causing this, or if you need more information.

Thanks
Carl-Eric

max · **Posted:** Sat Nov 22, 2003 6:22 pm

What happens in hibernnates log between those two statements ?

calle · **Joined:** Tue Sep 02, 2003 8:19 pm **Posts:** 19

Duh. I thought about enabling Hibernate logs just a few minutes before you sent this ;-)

Setting the Hibernate log level to DEBUG, I get tons of output between those two lines. No errors, it's seemingly all just DB-access. Which makes me wonder: Why does it do this? I called Hibernate.initialize() on the poll first, isn't this supposed to load the whole attached object graph? Or am I misunderstanding the semantics of initialize() now? It would certainly explain why it is taking more time than expected - though I still think it is slower than it should be.

Thanks
Carl-Eric

max · **Posted:** Sat Nov 22, 2003 7:30 pm

My best guess is that you are not using proxies nor lazy loading so you make Hibernate fetch the WHOLE objectgraph - which is not what you intend, right?

You say twice that you call initialize(), but you haven't showed code that actually call intialize() - have you ?

calle · **Joined:** Tue Sep 02, 2003 8:19 pm **Posts:** 19

I'm using proxies and lazy collections, because in most parts of my application I don't need the whole object graph. In this part, though, I want to get the whole graph/tree from the poll on downwards. Well, now that you say it, I do not want to get anything above the poll in the object graph (PollGroups).

Just before I get into the calls shown above, I call

Code:

t.initialize(p);

, which is a call to my DAO layer. The method in there looks like this:

Code:

    public void initialize(Persistable p) throws DAOException
    {
        try
        {
            Hibernate.initialize(p);
        }
        catch (HibernateException e)
        {
            log.warn(e);
            throw new DAOException(e);
        }
    }

Thinking about it now, I could initialize the questions collection of the poll with a fetch clause instead of loading the poll via session.load(), that would not go *up* the tree. But how do I get it to initialize everything from there on downwards without iterating through it myself? Currently I am iterating through it for other reasons, but that is incredibly slow, seemingly because each instance is only then fetched from the DB.

Thanks
Carl-Eric

max · **Posted:** Sun Nov 23, 2003 8:53 am

Okay i'm really puzzled about your questions ;)

First you say you have "problems" with initialize() and don't post code with initialize. Then you do post the code, but now mentions you use load() and still without the code showing that you do!

You say hibernate does a heck of a lot of db-access in between the two calls - then Hibernate must have been informed (either by code you have not shown me, or via the mappings by incorrect/misconfiguration of lazy loadings etc.) that it should fetch this data.

Your initial question just say you call iterateQuestions() - well that method calls iterate() which should ONLY make one query asking the db's for the identifiers of the questions....after that it uses the id's one at the time to perform a load()....but that should first happen when you actually perform the iteration.

So - i'm very doubtfull regarding that the performance penalty is at the iterator() (unless there are millions of Questions) - it is more likely close to your initialize() call.....and that should only be costfull if you have configured hibernate to load big parts of the objectgraph...

Check out the hibernate log and see what it is actually loading - it should explain the problem.

calle · **Joined:** Tue Sep 02, 2003 8:19 pm **Posts:** 19

Yeah, sorry, it's the weekend, I'm tired and confused myself ;-) It seems the above was mostly a braindump of various stages of debugging done here. Give me a few minutes and I'll reconstruct the whole thing in a more sensible manner.

calle · **Joined:** Tue Sep 02, 2003 8:19 pm **Posts:** 19

OK, I'll try to do this in a more sensible fashion now. I have
the following classes that are of interest now:

Poll:

Code:

<hibernate-mapping>
    <class
        name="de.....Poll"
        table="polls"
        proxy="de.....Poll"
    >
        <id name="id" unsaved-value="0">
            <generator class="native"/>
        </id>
        
        <list 
                name="questions"
                lazy="true"
                cascade="all-delete-orphan"
            >
            <key column="pollId"/>
            <index column="pollIndex"/>
            <one-to-many class="de.....Question"/>
        </list>
        
        <set 
                name="editors"
                lazy="true"
                cascade="none"
                table="pollEditors"
            >
                <key column="pollId"/>
                <many-to-many class="de.....User"/>
        </set>
        <list
              name="pictures"
              lazy="true"
              cascade="all"
           >
           <key column="pollId"/>
           <index column="pollIndex"/>
           <one-to-many class="de.....Picture"/>
        </list>
        <!-- this is a reference to a group of Polls that lives one step up in the object tree -->
        <many-to-one name="group" column="pollGroup"/>
        <property name="name">
            <column name="name" sql-type="text"/>
        </property>
        <property name="active"/>
        <property name="version"/>
        <many-to-one name="owner"/>
        <property name="addressText">
            <column name="addressText" sql-type="text"/>
        </property>
        <property name="futureContactText">
            <column name="futureContactText" sql-type="text"/>
        </property>
        <property name="endText">
            <column name="endText" sql-type="text"/>
        </property>
        <property name="introText">
            <column name="introText" sql-type="text"/>
        </property>
        <property name="fieldAddress1"/>
        <property name="fieldAddress2"/>
        <property name="fieldFirst"/>
        <property name="fieldLast"/>
        <property name="fieldZip"/>
        <property name="fieldCity"/>
        <property name="fieldState"/>
        <property name="fieldCountry"/>
        <property name="fieldPhone"/>
        <property name="fieldCell"/>
        <property name="fieldEmail"/>
        <property name="locale"/>
        <property name="theme"/>
    </class>
</hibernate-mapping>

Question:

Code:

<hibernate-mapping>
    <class
        name="de.....Question"
        table="questions"
        proxy="de.....Question"
    >
        <id name="id" unsaved-value="0">
            <generator class="native"/>
        </id>
        <!-- this is a reference to this question's root AnswerSet, see below -->
        <many-to-one name="answers" cascade="all"/>
        <many-to-one name="dependencies" cascade="all"/>
        <property name="identifier">
            <column name="identifier" sql-type="text"/>
        </property>
        <many-to-one name="picture"/>
        <property name="text">
            <column name="text" sql-type="text"/>
        </property>
        <property name="pictureEnabled"/>
        <property name="textEnabled"/>
        <many-to-one name="poll" column="pollId"/>
    </class>
</hibernate-mapping>

AbstractAnswer/AnswerSet/Answer:

Code:

<hibernate-mapping>
    <class
        name="de.....AbstractAnswer"
        table="answers"
        discriminator-value="abstract"
    >
        <id name="id" unsaved-value="0">
            <generator class="native"/>
        </id>
        <discriminator column="class"/>
        <many-to-one name="dependencies" outer-join="true" cascade="all"/>
        <property name="identifier">
            <column name="identifier" sql-type="text"/>
        </property>
        <many-to-one name="picture"/>
        <property name="text">
            <column name="text" sql-type="text"/>
        </property>
        <property name="selectable"/>
        <property name="pictureEnabled"/>
        <property name="textEnabled"/>
        <many-to-one name="parentQuestion"/>
        <many-to-one name="parentSet" column="setId"/>
        <subclass name="de.....Answer" discriminator-value="answer">
           <property name="showTextField"/>
        </subclass>
        <!-- an AnswerSet can contain any number of Answers and AnswerSets, thus building a tree of Answers -->
        <subclass name="de.....AnswerSet" discriminator-value="set">
            <property name="selectRequired"/>
            <property name="mode"/>
            <list 
                name="answers"
                lazy="true"
                cascade="all-delete-orphan"
            >
                <key column="setId"/>
                <index column="listIndex"/>
                <one-to-many class="de.....AbstractAnswer"/>
            </list>
            <property name="layout"/>
        </subclass>
    </class>
</hibernate-mapping>

UserResponse:

Code:

<hibernate-mapping>
    <class
        name="de.....UserResponse"
        table="userResponses"
    >
        <id name="id" unsaved-value="0">
            <generator class="native"/>
        </id>
        
        <set
            name="selectedAnswers"
            lazy="true"
            cascade="none"
            table="selectedAnswers"
        >
            <key column="userId"/>
            <many-to-many class="de.....AbstractAnswer" column="answerId"/>
        </set>
        <map
            name="textAnswers"
            lazy="true"
            cascade="all-delete-orphan"
            table="textAnswers"
        >
            <key column="uid"/>
            <index column="answer" type="long"/>
            <element type="string">
                <column name="text" sql-type="text"/>
            </element>
        </map>
        <property name="address1">
            <column name="address1" sql-type="text"/>
        </property>
        <property name="address2">
            <column name="address2" sql-type="text"/>
        </property>
        <property name="cellphone">
            <column name="cellphone" sql-type="text"/>
        </property>
        <property name="city">
            <column name="city" sql-type="text"/>
        </property>
        <property name="country">
            <column name="country" sql-type="text"/>
        </property>
        <property name="email">
            <column name="email" sql-type="text"/>
        </property>
        <property name="firstName">
            <column name="firstName" sql-type="text"/>
        </property>
        <property name="lastName">
            <column name="lastName" sql-type="text"/>
        </property>
        <property name="phone">
            <column name="phone" sql-type="text"/>
        </property>
        <property name="state">
            <column name="state" sql-type="text"/>
        </property>
        <property name="zip">
            <column name="zip" sql-type="text"/>
        </property>
        <many-to-one name="poll" cascade="none"/>
        <property name="pollVersion"/>
        <property name="futureContactAllowed"/>   
    </class>
</hibernate-mapping>

This is my hibernate.cfg.xml:

Code:

<hibernate-configuration>
    <session-factory>
        <property name="hibernate.connection.driver_class">org.postgresql.Driver</property>
        <property name="hibernate.connection.url">jdbc:postgresql://localhost/mafo2?charSet=UTF-8</property>
        <property name="hibernate.connection.username">calle</property>
        <property name="hibernate.connection.password">...</property>
        
        <!-- maximum number of connections in pool -->
        <property name="hibernate.dbcp.maxActive">50</property>
        <!-- what to do when no more connections in pool: 0=fail, 1=block and wait, 2=grow -->
        <property name="hibernate.dbcp.whenExhaustedAction">1</property>
        <property name="hibernate.dbcp.maxWait">60000</property>
        <!-- maximum number of idle connections in pool -->
        <property name="hibernate.dbcp.maxIdle">10</property>
        <!-- maximum number of cached prepared statements -->
        <property name="hibernate.dbcp.ps.maxActive">200</property>
        <property name="hibernate.dbcp.ps.whenExhaustedAction">1</property>
        <property name="hibernate.dbcp.ps.maxWait">60000</property>
        <property name="hibernate.dbcp.ps.maxIdle">200</property>
        
        <property name="hibernate.dbcp.testOnBorrow">true</property>
        
        <property name="hibernate.dialect">net.sf.hibernate.dialect.PostgreSQLDialect</property>
        
        <property name="hibernate.use_outer_join">true</property>
        <property name="hibernate.show_sql">true</property>
        <mapping resource="de/.../AbstractAnswer.hbm.xml"/>
        <mapping resource="de/.../AbstractDependency.hbm.xml"/>
        <mapping resource="de/.../Picture.hbm.xml"/>
        <mapping resource="de/.../Poll.hbm.xml"/>
        <mapping resource="de/.../PollGroup.hbm.xml"/>
        <mapping resource="de/.../Question.hbm.xml"/>
        <mapping resource="de/.../User.hbm.xml"/>
        <mapping resource="de/.../UserResponse.hbm.xml"/>
    </session-factory>
</hibernate-configuration>

I keep a SessionFactory in the servlet context of my web application, it is initialized the first time it is needed. Here is where I noticed the first interesting thing, although I never paid attention to it so far.

Code:

INFO ReflectHelper:328 - reflection optimizer disabled for: de.....Question, AssertionError: Assertion Failed

...and a number of similar messages, all related to exceptions thrown in my getter/setter methods. Many of my setters don't accept null as a valid argument, and many of the getters use an assertion to make sure they're not returning null. It looks like this is making Hibernate not use its reflection optimizer. Is this bad for performance further down the road? Or does it just increase startup time? Should I give Hibernate separate getter/setter methods to avoid this? That would be quite ugly.

Now, fast forward to the BeginPollAction, which is run when a user starts the poll to answer the questions (multiple-choice-style). This is the code that gets executed:

(BeginPollAction.java)

Code:

        DynaActionForm dform = (DynaActionForm) form;
        Long pId = (Long) dform.get("pollid");
        DAOTransaction t = null;
        try
        {
            t = DAOTransaction.beginTransaction();

DAOTransaction is my encapsulation of a Hibernate session and transaction. beginTransaction() creates a new instance and returns it.

(DAOTransaction.java)

Code:

    private DAOTransaction() throws DAOException
    {
        log.debug("Creating new DAOTransaction/Hibernate Session");
        try        
        {
            if (sessionFactory == null)
            {
                log.info("Creating new SessionFactory");
                // Use default hibernate.cfg.xml
                sessionFactory = new Configuration().configure()
                                                    .buildSessionFactory();
                log.info("SesionFactory created.");
            }

            this.session = sessionFactory.openSession();
            this.transaction = this.session.beginTransaction();
        }
        catch (HibernateException e)
        {
            log.warn("HibernateException in DAOTransaction", e);
            throw new DAOException(e);
        }
        log.debug("DAOTransaction created.");
    }

(BeginPollAction.java)

Code:

log.debug("Loading Poll.");
Poll p = t.getPollDAO().loadById(pId);

(PollDAO.java)

Code:

    public Poll loadById(Long id) throws DAOException
    {
        Poll p = null;

        try
        {
            p = (Poll) session.load(Poll.class, id);
        }
        catch (HibernateException e)
        {
            log.warn("Error while loading Poll", e);
            throw new DAOException(e);
        }

        return p;
    }

Next I try to initialize the Poll object, because I want to keep it all in the session context without going to the db again.

(BeginPollAction.java)

Code:

log.debug("Poll loaded - Initializing Object...");
t.initialize(p);

(DAOTransaction.java)

Code:

...as shown above in a previous post...

Now I create a new instance of the UserResponse object, that will gather all the answers the user gives during the poll.

Code:

log.debug("Creating UserResponse.");
UserResponse ures = new UserResponse(p);

(UserResponse.java)

Code:

    public UserResponse(Poll p)
    {
        setPoll(p); // plain setter
        setPollVersion(p.getVersion()); // plain setter
        setSelectedAnswers(new HashSet()); // plain setter
        initialize(p); // this one is interesting, see below
        questions = p.iterateQuestions(); // stores an iterator over the questions
    }
    
    /* This method iterates through the whole question/answer tree attached
     * to the poll and stores all concrete Answer objects in a flat Map
     */
    private void initialize(Poll p)
    {
        log.debug("Initializing UserResponse with poll");
        Iterator i = p.iterateQuestions(); // this method can be seen in a previous post
        
        Question q;
        log.debug("entering question loop");
        while (i.hasNext())
        {
            log.debug("getting question");
            q = (Question) i.next();
            log.debug("sending to processor method");
            processQuestion(q);
        }
        log.debug("UR init done.");
    }
    
    private void processQuestion(Question q)
    {
        // get the root AnswerSet and process it
        processAnswerSet(q.getAnswers());
    }
    
    private void processAnswerSet(AnswerSet set)
    {
        if (log.isDebugEnabled())
        {log.debug("processing answerset " + set.getId());} 
        // answerSetBuffer and answerBuffer are HashMaps
        answerSetBuffer.put(set.getId().toString(), set);

        Iterator i = set.iterateAnswers();
        AbstractAnswer a;

        while (i.hasNext())
        {
            a = (AbstractAnswer) i.next();

            if (a instanceof Answer)
            {
                answerBuffer.put(a.getId().toString(), a);
            }
            else if (a instanceof AnswerSet)
            {
                processAnswerSet((AnswerSet) a);
            }
        }
        if (log.isDebugEnabled())
        {log.debug("processing answerset " + set.getId() + " done.");} 
    }

Now for the logs during this:

Code:

36:29,994 DEBUG DAOTransaction:73 - Creating new DAOTransaction/Hibernate Session
36:30,001 DEBUG SessionImpl:413 - opened session
36:30,006 DEBUG JDBCTransaction:36 - begin
36:30,012 DEBUG DAOTransaction:93 - DAOTransaction created.
36:30,017 DEBUG BeginPollAction:82 - Loading Poll.
36:30,046 DEBUG SessionImpl:1752 - loading [de.....Poll#71]
36:32,002 DEBUG BeginPollAction:87 - Poll loaded - Initializing Object...
36:32,024 DEBUG SessionImpl:1843 - attempting to resolve [de.....Poll#71]
36:32,031 DEBUG SessionImpl:1887 - object not resolved in any cache [de.....Poll#71]
36:32,038 DEBUG EntityPersister:394 - Materializing entity: de.....Poll#71
36:32,046 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
36:32,052 DEBUG SessionFactoryImpl:526 - prepared statement get: select pollgrou1_.id as id0_, pollgrou1_.owner as owner0_, pollgrou1_.name as name0_, user2_.id as id1_, user2_.pollGroupCreator as pollGrou2_1_, user2_.admin as admin1_, user2_.login as login1_, user2_.name as name1_, user2_.password as password1_, user3_.id as id2_, user3_.pollGroupCreator as pollGrou2_2_, user3_.admin as admin2_, user3_.login as login2_, user3_.name as name2_, user3_.password as password2_, poll0_.id as id3_, poll0_.pollGroup as pollGroup3_, poll0_.name as name3_, poll0_.active as active3_, poll0_.version as version3_, poll0_.owner as owner3_, poll0_.addressText as addressT7_3_, poll0_.futureContactText as futureCo8_3_, poll0_.endText as endText3_, poll0_.introText as introText3_, poll0_.fieldAddress1 as fieldAd11_3_, poll0_.fieldAddress2 as fieldAd12_3_, poll0_.fieldFirst as fieldFirst3_, poll0_.fieldLast as fieldLast3_, poll0_.fieldZip as fieldZip3_, poll0_.fieldCity as fieldCity3_, poll0_.fieldState as fieldState3_, poll0_.fieldCountry as fieldCo18_3_, poll0_.fieldPhone as fieldPhone3_, poll0_.fieldCell as fieldCell3_, poll0_.fieldEmail as fieldEmail3_, poll0_.locale as locale3_, poll0_.theme as theme3_ from polls poll0_ left outer join pollgroups pollgrou1_ on poll0_.pollGroup=pollgrou1_.id left outer join users user2_ on pollgrou1_.owner=user2_.id left outer join users user3_ on poll0_.owner=user3_.id where poll0_.id=?
36:32,058 DEBUG SessionFactoryImpl:536 - preparing statement
36:32,125 DEBUG Loader:148 - processing result set
36:32,142 DEBUG Loader:260 - result row: 70, 2, 2, 71
36:32,149 DEBUG Loader:357 - Initializing object from ResultSet: 70
36:32,156 DEBUG Loader:413 - Hydrating entity: de.....PollGroup#70
36:32,193 DEBUG Loader:357 - Initializing object from ResultSet: 2
36:32,200 DEBUG Loader:413 - Hydrating entity: de.....User#2
36:32,208 DEBUG Loader:357 - Initializing object from ResultSet: 71
36:32,214 DEBUG Loader:413 - Hydrating entity: de.....Poll#71
36:32,239 DEBUG Loader:182 - done processing result set (1 rows)
36:32,247 DEBUG BatcherImpl:173 - done closing: 0 open PreparedStatements, 0 open ResultSets
36:32,253 DEBUG SessionFactoryImpl:554 - closing statement
36:32,260 DEBUG Loader:195 - total objects hydrated: 3
36:32,266 DEBUG SessionImpl:1954 - resolving associations for [de.....PollGroup#70]
36:32,357 DEBUG SessionImpl:1752 - loading [de.....User#2]
36:32,365 DEBUG SessionImpl:1843 - attempting to resolve [de.....User#2]
36:32,372 DEBUG SessionImpl:1858 - resolved object in session cache [de.....User#2]
36:32,380 DEBUG SessionImpl:1975 - done materializing entity [de.....PollGroup#70]
36:32,386 DEBUG SessionImpl:1954 - resolving associations for [de.....User#2]
36:32,393 DEBUG SessionImpl:1975 - done materializing entity [de.....User#2]
36:32,399 DEBUG SessionImpl:1954 - resolving associations for [de.....Poll#71]
36:32,421 DEBUG SessionImpl:1752 - loading [de.....PollGroup#70]
36:32,428 DEBUG SessionImpl:1843 - attempting to resolve [de.....PollGroup#70]
36:32,435 DEBUG SessionImpl:1858 - resolved object in session cache [de.....PollGroup#70]
36:32,441 DEBUG SessionImpl:1752 - loading [de.....User#2]
36:32,447 DEBUG SessionImpl:1843 - attempting to resolve [de.....User#2]
36:32,453 DEBUG SessionImpl:1858 - resolved object in session cache [de.....User#2]
36:32,462 DEBUG SessionImpl:1975 - done materializing entity [de.....Poll#71]
36:32,494 DEBUG BeginPollAction:92 - Poll initialized. Setting theme.

I don't understand this. I call initialize(), and it only initializes the direct references, not the collections. Is that correct? Am I misunderstanding initialize()?

Code:

16:36:32,502 DEBUG BeginPollAction:97 - Creating UserResponse.
16:36:32,510 DEBUG UserResponse:637 - Initializing UserResponse with poll

This is where I get the Iterator of the questions collection of my poll. For some reason Hibernate now begins to run through this collection instead of just giving me the iterator:

Code:

36:32,518 DEBUG SessionImpl:2888 - initializing collection [de.....Poll.questions#71]
36:32,526 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
36:32,533 DEBUG SessionFactoryImpl:526 - prepared statement get: select question0_.id as id__, question0_.pollIndex as pollIndex__, answerse1_.id as id0_, answerse1_.selectRequired as selectR13_0_, answerse1_.mode as mode0_, answerse1_.layout as layout0_, answerse1_.dependencies as dependen3_0_, answerse1_.identifier as identifier0_, answerse1_.picture as picture0_, answerse1_.text as text0_, answerse1_.selectable as selectable0_, answerse1_.pictureEnabled as pictureE8_0_, answerse1_.textEnabled as textEnab9_0_, answerse1_.parentQuestion as parentQ10_0_, answerse1_.setId as setId0_, dependen2_.id as id1_, dependen2_.combinationMode as combinat7_1_, dependen2_.dependingAnswer as dependin3_1_, dependen2_.dependingQuestion as dependin4_1_, dependen2_.setId as setId1_, abstract3_.id as id2_, abstract3_.class as class2_, abstract3_.dependencies as dependen3_2_, abstract3_.identifier as identifier2_, abstract3_.picture as picture2_, abstract3_.text as text2_, abstract3_.selectable as selectable2_, abstract3_.pictureEnabled as pictureE8_2_, abstract3_.textEnabled as textEnab9_2_, abstract3_.parentQuestion as parentQ10_2_, abstract3_.setId as setId2_, abstract3_.showTextField as showTex12_2_, abstract3_.selectRequired as selectR13_2_, abstract3_.mode as mode2_, abstract3_.layout as layout2_, picture4_.id as id3_, picture4_.type as type3_, picture4_.name as name3_, picture4_.pollId as pollId3_, picture4_.filename as filename3_, picture5_.id as id4_, picture5_.type as type4_, picture5_.name as name4_, picture5_.pollId as pollId4_, picture5_.filename as filename4_, picture6_.id as id5_, picture6_.type as type5_, picture6_.name as name5_, picture6_.pollId as pollId5_, picture6_.filename as filename5_, question0_.id as id6_, question0_.answers as answers6_, question0_.dependencies as dependen3_6_, question0_.identifier as identifier6_, question0_.picture as picture6_, question0_.text as text6_, question0_.pictureEnabled as pictureE7_6_, question0_.textEnabled as textEnab8_6_, question0_.pollId as pollId6_ from questions question0_ left outer join answers answerse1_ on question0_.answers=answerse1_.id left outer join dependencies dependen2_ on answerse1_.dependencies=dependen2_.id left outer join answers abstract3_ on dependen2_.dependingAnswer=abstract3_.id left outer join pictures picture4_ on abstract3_.picture=picture4_.id left outer join pictures picture5_ on answerse1_.picture=picture5_.id left outer join pictures picture6_ on question0_.picture=picture6_.id where question0_.pollId=?
36:32,540 DEBUG SessionFactoryImpl:536 - preparing statement
36:32,686 DEBUG Loader:148 - processing result set
36:32,695 DEBUG Loader:260 - result row: 73, 74, 73, null, null, null, 72
36:32,704 DEBUG Loader:357 - Initializing object from ResultSet: 73
36:32,711 DEBUG Loader:413 - Hydrating entity: de.....AnswerSet#73
36:32,719 DEBUG Loader:357 - Initializing object from ResultSet: 74
36:32,726 DEBUG Loader:413 - Hydrating entity: de.....DependencySet#74
36:32,734 DEBUG Loader:357 - Initializing object from ResultSet: 72
36:32,741 DEBUG Loader:413 - Hydrating entity: de.....Question#72
36:32,758 DEBUG SessionImpl:1752 - loading [de.....Question#72]
36:32,773 DEBUG SessionImpl:1843 - attempting to resolve [de.....Question#72]
36:32,781 DEBUG SessionImpl:1858 - resolved object in session cache [de.....Question#72]

...and so on for about 1900 (!) lines until:

Code:

16:36:52,382 DEBUG UserResponse:641 - entering question loop

This is the next method call in UserResponse. It spends 1900 lines retrieving instances from this collection when I just want to get the Iterator.

Code:

36:52,390 DEBUG UserResponse:644 - getting question
36:52,398 DEBUG UserResponse:646 - sending to processor method
36:52,406 DEBUG UserResponse:660 - processing answerset 89
36:52,413 DEBUG SessionImpl:2888 - initializing collection [de.....AnswerSet.answers#89]
36:52,419 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
36:52,426 DEBUG SessionFactoryImpl:526 - prepared statement get: select answers0_.id as id__, answers0_.listIndex as listIndex__, dependen1_.id as id0_, dependen1_.combinationMode as combinat7_0_, dependen1_.dependingAnswer as dependin3_0_, dependen1_.dependingQuestion as dependin4_0_, dependen1_.setId as setId0_, dependen2_.id as id1_, dependen2_.combinationMode as combinat7_1_, dependen2_.dependingAnswer as dependin3_1_, dependen2_.dependingQuestion as dependin4_1_, dependen2_.setId as setId1_, picture3_.id as id2_, picture3_.type as type2_, picture3_.name as name2_, picture3_.pollId as pollId2_, picture3_.filename as filename2_, answers0_.id as id3_, answers0_.class as class3_, answers0_.dependencies as dependen3_3_, answers0_.identifier as identifier3_, answers0_.picture as picture3_, answers0_.text as text3_, answers0_.selectable as selectable3_, answers0_.pictureEnabled as pictureE8_3_, answers0_.textEnabled as textEnab9_3_, answers0_.parentQuestion as parentQ10_3_, answers0_.setId as setId3_, answers0_.showTextField as showTex12_3_, answers0_.selectRequired as selectR13_3_, answers0_.mode as mode3_, answers0_.layout as layout3_ from answers answers0_ left outer join dependencies dependen1_ on answers0_.dependencies=dependen1_.id left outer join dependencies dependen2_ on dependen1_.setId=dependen2_.id left outer join pictures picture3_ on answers0_.picture=picture3_.id where answers0_.setId=?
36:52,432 DEBUG SessionFactoryImpl:536 - preparing statement
36:52,464 DEBUG Loader:148 - processing result set

Then when I go and actually iterate through the questions and answers in the initialize/process methods of UserResponse, it only then starts to load the objects hidden in the collections further down the tree. If I have in fact misunderstood initialize() then this is understandable, but still incredibly slow. It spends about 2-3 seconds between this:

Code:

36:52,406 DEBUG UserResponse:660 - processing answerset 89
36:52,413 DEBUG SessionImpl:2888 - initializing collection [de.....AnswerSet.answers#89]
36:52,419 DEBUG BatcherImpl:166 - about to open: 0 open PreparedStatements, 0 open ResultSets
36:52,426 DEBUG SessionFactoryImpl:526 - prepared statement get: select answers0_.id as id__, answers0_.listIndex as listIndex__, dependen1_.id as id0_, dependen1_.combinationMode as combinat7_0_, dependen1_.dependingAnswer as dependin3_0_, dependen1_.dependingQuestion as dependin4_0_, dependen1_.setId as setId0_, dependen2_.id as id1_, dependen2_.combinationMode as combinat7_1_, dependen2_.dependingAnswer as dependin3_1_, dependen2_.dependingQuestion as dependin4_1_, dependen2_.setId as setId1_, picture3_.id as id2_, picture3_.type as type2_, picture3_.name as name2_, picture3_.pollId as pollId2_, picture3_.filename as filename2_, answers0_.id as id3_, answers0_.class as class3_, answers0_.dependencies as dependen3_3_, answers0_.identifier as identifier3_, answers0_.picture as picture3_, answers0_.text as text3_, answers0_.selectable as selectable3_, answers0_.pictureEnabled as pictureE8_3_, answers0_.textEnabled as textEnab9_3_, answers0_.parentQuestion as parentQ10_3_, answers0_.setId as setId3_, answers0_.showTextField as showTex12_3_, answers0_.selectRequired as selectR13_3_, answers0_.mode as mode3_, answers0_.layout as layout3_ from answers answers0_ left outer join dependencies dependen1_ on answers0_.dependencies=dependen1_.id left outer join dependencies dependen2_ on dependen1_.setId=dependen2_.id left outer join pictures picture3_ on answers0_.picture=picture3_.id where answers0_.setId=?
36:52,432 DEBUG SessionFactoryImpl:536 - preparing statement
36:52,464 DEBUG Loader:148 - processing result set
36:52,472 DEBUG Loader:260 - result row: 92, null, null, 91
36:52,480 DEBUG Loader:357 - Initializing object from ResultSet: 92
36:52,487 DEBUG Loader:413 - Hydrating entity: de.....DependencySet#92
36:52,494 DEBUG Loader:357 - Initializing object from ResultSet: 91
36:52,501 DEBUG Loader:413 - Hydrating entity: de.....Answer#91
36:52,508 DEBUG SessionImpl:1752 - loading [de.....AbstractAnswer#91]
36:52,515 DEBUG SessionImpl:1843 - attempting to resolve [de.....AbstractAnswer#91]
36:52,522 DEBUG SessionImpl:1858 - resolved object in session cache [de.....AbstractAnswer#91]

...lots more like that...

and this:

Code:

16:36:54,621 DEBUG UserResponse:680 - processing answerset 89 done.

This is then repeated for quite a number of AnswerSets, and takes about as long each time.

I admit that this is partly due to having to output tons of debug lines. But even with debugging turned to WARN for Hibernate, the whole iteration through a Poll with 21 questions, each having between 3 and 10 Answers or AnswerSets (which may have up to 10 Answers themselves) still takes up to 20 seconds. This is almost a showstopper for me.

I'm still not thinking that Hibernate is causing this, so I must have done something wrong. The question remains: what? Am I doing something bad in my mappings that I have overlooked? Or is there anything else I could/should do?

Thanks for your help!
Carl-Eric

PS: Sorry for this huge post, but I tried to show exactly what happens.

emmanuel · **Posted:** Sun Nov 23, 2003 1:08 pm

calle wrote:

Many of my setters don't accept null as a valid argument, and many of the getters use an assertion to make sure they're not returning null. It looks like this is making Hibernate not use its reflection optimizer. Is this bad for performance further down the road?

Not using reflection optimizer isn't a big perf improvement (compared to DB queries).

calle wrote:

16:36:32,052 DEBUG SessionFactoryImpl:526 - prepared statement get: select pollgrou1_.id as id0_, pollgrou1_.owner as owner0_, pollgrou1_.name as name0_, user2_.id as id1_, user2_.pollGroupCreator as pollGrou2_1_, user2_.admin as admin1_, user2_.login as login1_, user2_.name as name1_, user2_.password as password1_, user3_.id as id2_, user3_.pollGroupCreator as pollGrou2_2_, user3_.admin as admin2_, user3_.login as login2_, user3_.name as name2_, user3_.password as password2_, poll0_.id as id3_, poll0_.pollGroup as pollGroup3_, poll0_.name as name3_, poll0_.active as active3_, poll0_.version as version3_, poll0_.owner as owner3_, poll0_.addressText as addressT7_3_, poll0_.futureContactText as futureCo8_3_, poll0_.endText as endText3_, poll0_.introText as introText3_, poll0_.fieldAddress1 as fieldAd11_3_, poll0_.fieldAddress2 as fieldAd12_3_, poll0_.fieldFirst as fieldFirst3_, poll0_.fieldLast as fieldLast3_, poll0_.fieldZip as fieldZip3_, poll0_.fieldCity as fieldCity3_, poll0_.fieldState as fieldState3_, poll0_.fieldCountry as fieldCo18_3_, poll0_.fieldPhone as fieldPhone3_, poll0_.fieldCell as fieldCell3_, poll0_.fieldEmail as fieldEmail3_, poll0_.locale as locale3_, poll0_.theme as theme3_ from polls poll0_ left outer join pollgroups pollgrou1_ on poll0_.pollGroup=pollgrou1_.id left outer join users user2_ on pollgrou1_.owner=user2_.id left outer join users user3_ on poll0_.owner=user3_.id where poll0_.id=?

Beware the many to one. a many-to-one relation on a non proxied object (on the other side) will load the object on the other side. And this is cascaded.
I see in this request pollgroups, user (related to pollgroups), user related to poll.

calle wrote:

I don't understand this. I call initialize(), and it only initializes the direct references, not the collections. Is that correct? Am I misunderstanding initialize()?

This is the expected behaviour. If you want to init collections, do

Code:

Hibernate.initialize( cat.getKittens() )

To sumarize, beware many-to-one not proxied. Each "parent" object will be loaded and filled.