-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 3 posts ] 
Author Message
 Post subject: Performanz-Problem von Criteria-API Abfrage
PostPosted: Wed Jan 25, 2006 8:52 am 
Newbie

Joined: Thu Nov 17, 2005 6:35 am
Posts: 7
Hi!

Ich verwende die Criteria-API für eine Abfrage, und sie dauert minutenlang, obwohl eigentlich nur 147 Datensätze vom Typ Durchfuehrung (Subklasse von DfVorlageBasis) abgefragt werden. Das Problem ist vermutlich, dass sämtliche Collections geladen werden, obwohl sie eigentlich als lazy konfiguriert sind.
Liegt trotzdem ein Konfigurationsfehler vor?

Hibernate version:
3.1rc3

Mapping documents:
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">

<hibernate-mapping
package="de.fhzw.portal.umfragesystem.model.domainmodel.umfrage">

<class name="DfVorlageBasis" table="DF_VORLAGE_BASIS" lazy="true"
dynamic-insert="true" dynamic-update="true">

<id name="id" unsaved-value="0">
<generator class="increment" />
</id>

<property name="bezeichnung" not-null="true" />
<property name="beschreibung" />
<property name="begrText" column="BEGR_TEXT" />
<property name="begrTextAnzeige" column="BEGR_TEXT_ANZEIGE"
not-null="true" />
<property name="abschText" column="ABSCH_TEXT" />
<property name="abschTextAnzeige" column="ABSCH_TEXT_ANZEIGE"
not-null="true" />
<property name="teilnSicherheit" column="TEILN_SICHERHEIT"
not-null="true" />
<property name="auswSicherheitSuper" column="AUSW_SICHERHEIT_SUPER"
not-null="true" />
<property name="auswSicherheitSub" column="AUSW_SICHERHEIT_SUB"
not-null="true" />
<property name="kennwort" />

<property name="umfrBeginn" type="timestamp" column="UMFR_BEGINN"
not-null="true" />
<property name="umfrEnde" type="timestamp" column="UMFR_ENDE"
not-null="true" />
<property name="ergPubBeginnOpt" column="ERG_PUB_BEGINN_OPT"
not-null="true" />
<property name="ergPubBeginn" type="timestamp" column="ERG_PUB_BEGINN" />
<property name="ergPubEnde" type="timestamp" column="ERG_PUB_ENDE" />
<property name="ergPubAnzahl" column="ERG_PUB_ANZAHL" />
<property name="studentenOpt" column="STUDENTEN_OPT" not-null="true" />
<property name="semester" not-null="true" />
<property name="stgang" not-null="true" />
<property name="fach" not-null="true" />
<property name="gruppe" />
<property name="dozent" not-null="true" />
<property name="fachsem" not-null="true" />
<property name="mitarbeiterOpt" column="MITARBEITER_OPT" not-null="true" />
<property name="fachbereichStud" column="FACHBEREICH_STUD"
not-null="true" />
<property name="fachbereichMit" column="FACHBEREICH_MIT" not-null="true" />
<property name="bereich" not-null="true" />

<!-- Die folgende Formula zaehlt die Fragen einer Durchfuehrung/Vorlage;
sie zaehlt nicht die Fragen von zusammengesetzten Fragen mit,
da Fragen von zusammengesetzten Fragen momentan nur die
zusammengesetzte Frage referenzieren, und nicht die Umfrage.
-->
<property name="anzahlFragen"
formula="(select count(f.id) from Frage f, DF_Vorlage_Basis dvb where
id = dvb.id and dvb.umfrage = f.frage_umfrage)" />

<many-to-one name="umfrage" class="Umfrage" not-null="true" lazy="false"
cascade="save-update" />

<set name="auswertungsberechtigte" lazy="true" inverse="true"
cascade="all-delete-orphan">
<key column="DF_VORLAGE_BASIS"/>
<one-to-many class="Auswertungsberechtigt" />
</set>


<joined-subclass name="Durchfuehrung" lazy="true">
<key column="ID" />
<property name="freigegeben" not-null="true" />
<property name="erneuteDf" column="ERNEUTE_DF" not-null="true" />
<property name="generiert" not-null="true" />
<property name="anzahlRegTeilnehmer" column="ANZAHL_REG_TEILNEHMER"
not-null="true" />
<set name="antwortsaetze" lazy="true" inverse="true" batch-size="16"
cascade="all-delete-orphan">
<key column="DURCHFUEHRUNG" />
<one-to-many class="Antwortsatz" />
</set>
<set name="bereitsabgestimmte" lazy="true" inverse="true"
cascade="all-delete-orphan">
<key column="DURCHFUEHRUNG" />
<one-to-many class="Bereitsabgestimmt" />
</set>
<set name="tanbloecke" lazy="true" inverse="true"
cascade="all-delete-orphan">
<key column="DURCHFUEHRUNG"/>
<one-to-many class="Tanblock" />
</set>
</joined-subclass>

<joined-subclass name="Vorlage" lazy="true">
<key column="ID" />
<property name="gemeinsam" not-null="true" />
</joined-subclass>

</class>
</hibernate-mapping>

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">

<hibernate-mapping package="de.fhzw.portal.umfragesystem.model.domainmodel.umfrage">
<class name="Umfrage" lazy="true" dynamic-insert="true" dynamic-update="true">

<id name="id" unsaved-value="0">
<generator class="increment" />
</id>

<property name="umfrTyp" column="UMFR_TYP" not-null="true" />
<property name="fragenAufteilung" column="FRAGEN_AUFTEILUNG"
not-null="true" />
<property name="bearbZeit" column="BEARB_ZEIT" />
<property name="fragebogenLayout" column="FRAGEBOGEN_LAYOUT"
not-null="true" />
<property name="layoutFile" column="FRAGEBOGEN_LAYOUT_FILE" />
<property name="autor" not-null="true" />
<property name="autorName" column="AUTOR_NAME" />
<property name="maxSeitenzahl" column="MAX_SEITENZAHL" not-null="true" />

<set name="fragen" lazy="true" inverse="true" cascade="all-delete-orphan">
<key column="FRAGE_UMFRAGE" />
<one-to-many class="Frage" />
</set>

</class>
</hibernate-mapping>


Code between sessionFactory.openSession() and session.close():
Ich verwendte Container Managed Transactions (JBoss). Der folgende Methodenaufruf mit der DB-Abfrage wird von einer Stateless Session Bean ausgeführt. Die Abfrage dauert minutenlang (9+ Minuten vergehen zwischen Methodeneintritt und Methodenaustritt, obwohl eigentlich nur 147 Datensätze gefunden werden).

public List findDfByAutorRoleUmfrTypUmfrZust(Integer uId,
boolean forUmfrSuperManager, Character umfrTyp, Character umfrZust)
throws InfrastructureException {
DurchfuehrungDAO.log.info("entering findDfByAutorRoleUmfrTypUmfrZust()");
DurchfuehrungDAO.log.debug("Params: uId=" + uId + ", umfrTyp=" + umfrTyp +
", umfrZust=" + umfrZust);

if (uId == null || umfrTyp == null || umfrZust == null) {
DurchfuehrungDAO.log.error("Null Parameter!");
throw new IllegalArgumentException("Null Parameter!");
}

Session session = HibernateUtil.getUmfrageSession();
Criteria criteria = session.createCriteria(Durchfuehrung.class);
List list = null;

switch (umfrZust.charValue()) {
case UmfrageConstants.NICHT_FREI_CHR:
criteria = criteria.add(Property.forName("freigegeben").eq(
Boolean.FALSE));
break;
case UmfrageConstants.FREI_CHR:
criteria = criteria.add(Property.forName("freigegeben").eq(
Boolean.TRUE));
break;
case UmfrageConstants.NICHT_BEG_CHR:
criteria = criteria.add(Property.forName("umfrBeginn").gt(new Date()));
break;
case UmfrageConstants.BEG_CHR:
criteria = criteria.add(Property.forName("umfrBeginn").lt(new Date()));
break;
case UmfrageConstants.NICHT_BEENDET_CHR:
criteria = criteria.add(Property.forName("umfrEnde").gt(new Date()));
break;
case UmfrageConstants.BEENDET_CHR:
criteria = criteria.add(Property.forName("umfrEnde").lt(new Date()));
break;
case UmfrageConstants.OHNE_ERG_CHR:
criteria = criteria.add(Restrictions.sizeEq("antwortsaetze", 0));
break;
case UmfrageConstants.MIT_ERG_CHR:
criteria = criteria.add(Restrictions.sizeGt("antwortsaetze", 0));
break;
default:
DurchfuehrungDAO.log.debug("Umfragezustand not supported: " + umfrZust);
throw new IllegalArgumentException("umfrZust nicht unterstuetzt!");
}

criteria = criteria.createCriteria("umfrage");

if (forUmfrSuperManager) {
criteria = criteria.add(Property.forName("autor").ne(uId)); // nicht vom Autor
} else {
criteria = criteria.add(Property.forName("autor").eq(uId)); // vom Autor
}

criteria = criteria.add(Property.forName("umfrTyp").eq(umfrTyp));

try {

list = criteria.list();

} catch(HibernateException he) {
DurchfuehrungDAO.log.error("HibernateException while trying to query " +
"Durchfuehrung and Umfrage!", he);
throw new InfrastructureException(he);
}
DurchfuehrungDAO.log.debug("Durchfuehrungen = " + list);
DurchfuehrungDAO.log.info("leaving findDfByAutorRoleUmfrTypUmfrZust()");
return list;
}


Full stack trace of any exception that occurs:
Keine Exception.

Name and version of the database you are using:
MaxDB 7.5

The generated SQL (show_sql=true):
Siehe nächster Punkt.

Debug level Hibernate log excerpt:

Der Log-Datei (knapp 200 MB für den Methodenaufruf, Hibernate Debug Level) lässt sich entnehmen, dass Hibernate komischerweise auch Collections lädt, die eigentlich mit lazy="true" konfiguriert sind, z. B.:

loading collection: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Frage.antworten#435]
2006-01-24 22:48:47,640 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-01-24 22:48:47,640 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-01-24 22:48:47,640 DEBUG [org.hibernate.SQL] select antworten0_.FRAGE_ANTWORT as FRAGE4_3_, antworten0_.id as id3_, antworten0_.id as id0_2_, antworten0_.typ as typ0_2_, antworten0_.anmerkungen as anmerkun3_0_2_, antworten0_.FRAGE_ANTWORT as FRAGE4_0_2_, antworten0_.ANTWORTSATZ_ANTWORTEN as ANTWORTS5_0_2_, antworten0_.ZUSAMMENGESANTWORT_ANTWORTEN as ZUSAMMEN6_0_2_, decode(antworten0_.id, antworten0_1_.ID, 1, antworten0_2_.ID, 2, antworten0_3_.ID, 3, antworten0_4_.ID, 4, antworten0_5_.ID, 5, 0) as clazz_2_, textantwor1_.id as id25_0_, textantwor1_.text as text25_0_, textantwor1_.FREIEANTWORT_TEXT as FREIEANT3_25_0_, auswahlant2_.id as id7_1_, auswahlant2_.auswahl as auswahl7_1_, auswahlant2_.textantwort as textantw3_7_1_, auswahlant2_.EINFACHAUSWANTW_AUSWAHL as EINFACHA4_7_1_, auswahlant2_.MEHRFACHAUSWANTW_AUSWAHL as MEHRFACH5_7_1_, auswahlant2_.MTRXTEILANTW_AUSWAHL as MTRXTEIL6_7_1_ from Antwort antworten0_, Freiefrageantwort antworten0_1_, Einfachauswahlfrageantwort antworten0_2_, Mehrfachauswahlfrageantwort antworten0_3_, Matrixfrageantwort antworten0_4_, Zusammengesetztefrageantwort antworten0_5_, Textantwort textantwor1_, Auswahlantwort auswahlant2_ where antworten0_.id=textantwor1_.FREIEANTWORT_TEXT(+) and antworten0_.id=auswahlant2_.EINFACHAUSWANTW_AUSWAHL(+) and antworten0_.id=antworten0_1_.ID(+) and antworten0_.id=antworten0_2_.ID(+) and antworten0_.id=antworten0_3_.ID(+) and antworten0_.id=antworten0_4_.ID(+) and antworten0_.id=antworten0_5_.ID(+) and antworten0_.FRAGE_ANTWORT=?
2006-01-24 22:48:47,640 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement


Top
 Profile  
 
 Post subject:
PostPosted: Thu Jan 26, 2006 8:15 am 
Expert
Expert

Joined: Tue Nov 23, 2004 7:00 pm
Posts: 570
Location: mostly Frankfurt Germany
Hallo,
ich habe mir das jetzt 5 Minuten angeguckt, aber zumindestens ich werde daraus nicht schlau.

Bitte formatiere jeden Block einzeln mit code tags.
Es ist nicht erkennbar, ob die query dadurch entsteht, dass eine Bedingung irgendwas dazu joinen muss. Vielleicht baust Du mal einen simplen Testcase, ohne if, der klar zeigt, welche Criteria query eigentlich abgefragt wid.
Mögliches Problem:
Du beziehst Dich möglicherweise auf den Frageanworttyp, für den alle Subclasses von Frage dazugejoint werden müssen.

Gruß Sebastian
Code:
select
antworten0_.FRAGE_ANTWORT as FRAGE4_3_, antworten0_.id as id3_,
antworten0_.id as id0_2_, antworten0_.typ as typ0_2_, antworten0_.anmerkungen as anmerkun3_0_2_,
antworten0_.FRAGE_ANTWORT as FRAGE4_0_2_, antworten0_.ANTWORTSATZ_ANTWORTEN as ANTWORTS5_0_2_,
antworten0_.ZUSAMMENGESANTWORT_ANTWORTEN as ZUSAMMEN6_0_2_,

decode(antworten0_.id, antworten0_1_.ID, 1, antworten0_2_.ID, 2, antworten0_3_.ID, 3, antworten0_4_.ID, 4,
antworten0_5_.ID, 5, 0) as clazz_2_,

textantwor1_.id as id25_0_, textantwor1_.text as text25_0_, textantwor1_.FREIEANTWORT_TEXT as FREIEANT3_25_0_,

auswahlant2_.id as id7_1_, auswahlant2_.auswahl as auswahl7_1_, auswahlant2_.textantwort as textantw3_7_1_,
auswahlant2_.EINFACHAUSWANTW_AUSWAHL as EINFACHA4_7_1_, auswahlant2_.MEHRFACHAUSWANTW_AUSWAHL as MEHRFACH5_7_1_,
auswahlant2_.MTRXTEILANTW_AUSWAHL as MTRXTEIL6_7_1_

from Antwort antworten0_, Freiefrageantwort antworten0_1_, Einfachauswahlfrageantwort antworten0_2_,
Mehrfachauswahlfrageantwort antworten0_3_,
Matrixfrageantwort antworten0_4_,
Zusammengesetztefrageantwort antworten0_5_,
Textantwort textantwor1_,
Auswahlantwort auswahlant2_

where
antworten0_.id=textantwor1_.FREIEANTWORT_TEXT(+)

and antworten0_.id=auswahlant2_.EINFACHAUSWANTW_AUSWAHL(+)
and antworten0_.id=antworten0_1_.ID(+)
and antworten0_.id=antworten0_2_.ID(+)
and antworten0_.id=antworten0_3_.ID(+)
and antworten0_.id=antworten0_4_.ID(+)
and antworten0_.id=antworten0_5_.ID(+)
and antworten0_.FRAGE_ANTWORT=?

_________________
Best Regards
Sebastian
---
Training for Hibernate and Java Persistence
Tutorials for Hibernate, Spring, EJB, JSF...
eBook: Hibernate 3 - DeveloperGuide
Paper book: Hibernate 3 - Das Praxisbuch
http://www.laliluna.de


Top
 Profile  
 
 Post subject:
PostPosted: Thu Jan 26, 2006 10:32 am 
Newbie

Joined: Thu Nov 17, 2005 6:35 am
Posts: 7
Hi!

Zunächst mal vielen Dank für deine Hilfe. Also in der switch/case Anweisung wird folgender Fall ausgeführt:


Code:
case UmfrageConstants.FREI_CHR:
criteria = criteria.add(Property.forName("freigegeben").eq(
Boolean.TRUE));
break;


Diese Bedingung bezieht sich auf ein Property der Klasse Durchfuehrung, hat also nichts mit Fragen oder Antworten zu tun.

Code:
criteria = criteria.createCriteria("umfrage");


Eine Durchfuehrung referenziert eine Umfrage. Die Umfrage muss auch bestimmte Kriterien erfüllen, die im Folgenden erläutert werden.

Code:
if (forUmfrSuperManager) {
criteria = criteria.add(Property.forName("autor").ne(uId)); // nicht vom Autor
} else {
criteria = criteria.add(Property.forName("autor").eq(uId)); // vom Autor
}


In diesem Teil wird die erste Abfrage ausgeführt (forUmfrSuperManager ist wahr). Das Criteria bezieht sich auf ein Property einer Umfrage, von der jeweils eine von einer Durchfuehrung referenziert wird. Es sind also die Durchfuehrungen gesucht, die auf eine Umfrage verweisen, deren Autor nicht der uId entspricht.

Code:
criteria = criteria.add(Property.forName("umfrTyp").eq(umfrTyp));


Diese Bedingung bezieht sich auch auf ein Property einer Umfrage. Es sind also nur die Durchfuehrungen gesucht, die eine Umfrage eines bestimmten Umfragetyps referenzieren.

Mehr Bedingungen werden nicht gestellt. Die hier berücksichtigten Bedingungen beziehen sich also nur auf Properties von Durchfuehrung und Umfrage, und nicht auf Collections. Trotzdem werden bei der Abfrage massiv Collections abgefragt und initialisiert, die von Durchfuehrung oder Umfrage verwendet werden, aber in den Mapping Dateien als "lazy" konfiguriert sind. Mir scheint, als wird diese Konfiguration völlig ignoriert.

Im Folgenden die initiale SQL-Abfrage:

Code:
2006-01-24 22:48:35,656 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4661818608447488
2006-01-24 22:48:35,656 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-01-24 22:48:35,656 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-01-24 22:48:35,656 DEBUG [org.hibernate.SQL] select this_.ID as id12_1_, this_1_.bezeichnung as bezeichn2_12_1_, this_1_.beschreibung as beschrei3_12_1_, this_1_.BEGR_TEXT as BEGR4_12_1_, this_1_.BEGR_TEXT_ANZEIGE as BEGR5_12_1_, this_1_.ABSCH_TEXT as ABSCH6_12_1_, this_1_.ABSCH_TEXT_ANZEIGE as ABSCH7_12_1_, this_1_.TEILN_SICHERHEIT as TEILN8_12_1_, this_1_.AUSW_SICHERHEIT_SUPER as AUSW9_12_1_, this_1_.AUSW_SICHERHEIT_SUB as AUSW10_12_1_, this_1_.kennwort as kennwort12_1_, this_1_.UMFR_BEGINN as UMFR12_12_1_, this_1_.UMFR_ENDE as UMFR13_12_1_, this_1_.ERG_PUB_BEGINN_OPT as ERG14_12_1_, this_1_.ERG_PUB_BEGINN as ERG15_12_1_, this_1_.ERG_PUB_ENDE as ERG16_12_1_, this_1_.ERG_PUB_ANZAHL as ERG17_12_1_, this_1_.STUDENTEN_OPT as STUDENTEN18_12_1_, this_1_.semester as semester12_1_, this_1_.stgang as stgang12_1_, this_1_.fach as fach12_1_, this_1_.gruppe as gruppe12_1_, this_1_.dozent as dozent12_1_, this_1_.fachsem as fachsem12_1_, this_1_.MITARBEITER_OPT as MITARBE25_12_1_, this_1_.FACHBEREICH_STUD as FACHBER26_12_1_, this_1_.FACHBEREICH_MIT as FACHBER27_12_1_, this_1_.bereich as bereich12_1_, this_1_.umfrage as umfrage12_1_, this_.freigegeben as freigege2_13_1_, this_.ERNEUTE_DF as ERNEUTE3_13_1_, this_.generiert as generiert13_1_, this_.ANZAHL_REG_TEILNEHMER as ANZAHL5_13_1_, (select count(f.id) from Frage f, DF_Vorlage_Basis dvb where          this_1_.id = dvb.id and dvb.umfrage = f.frage_umfrage) as formula0_1_, umfrage1_.id as id26_0_, umfrage1_.UMFR_TYP as UMFR2_26_0_, umfrage1_.FRAGEN_AUFTEILUNG as FRAGEN3_26_0_, umfrage1_.BEARB_ZEIT as BEARB4_26_0_, umfrage1_.FRAGEBOGEN_LAYOUT as FRAGEBOGEN5_26_0_, umfrage1_.FRAGEBOGEN_LAYOUT_FILE as FRAGEBOGEN6_26_0_, umfrage1_.autor as autor26_0_, umfrage1_.AUTOR_NAME as AUTOR8_26_0_, umfrage1_.MAX_SEITENZAHL as MAX9_26_0_ from Durchfuehrung this_, DF_VORLAGE_BASIS this_1_, Umfrage umfrage1_ where this_1_.umfrage=umfrage1_.id and this_.ID=this_1_.id and this_.freigegeben=? and umfrage1_.autor<>? and umfrage1_.UMFR_TYP=?
2006-01-24 22:48:35,656 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
2006-01-24 22:48:35,671 DEBUG [org.hibernate.type.BooleanType] binding 'true' to parameter: 1
2006-01-24 22:48:35,671 DEBUG [org.hibernate.type.IntegerType] binding '66' to parameter: 2
2006-01-24 22:48:35,671 DEBUG [org.hibernate.type.CharacterType] binding '1' to parameter: 3
2006-01-24 22:48:38,437 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-01-24 22:48:38,437 DEBUG [org.hibernate.loader.Loader] processing result set
...


Zu Beginn der Log-Datei sieht die Verarbeitung des ResultSet dann aus wie folgt:

Code:
result set row: 0
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.IntegerType] returning '10' as column: id26_0_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.IntegerType] returning '10' as column: id12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#10], EntityKey[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung#10]
2006-01-24 22:48:38,453 DEBUG [org.hibernate.loader.Loader] Initializing object from ResultSet: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#10]
2006-01-24 22:48:38,453 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#10]
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.CharacterType] returning '1' as column: UMFR2_26_0_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.CharacterType] returning '2' as column: FRAGEN3_26_0_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.ShortType] returning '1' as column: BEARB4_26_0_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.CharacterType] returning '1' as column: FRAGEBOGEN5_26_0_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.StringType] returning null as column: FRAGEBOGEN6_26_0_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.IntegerType] returning '2062' as column: autor26_0_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.StringType] returning 'Hettel, Jörg (jhe)' as column: AUTOR8_26_0_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.ShortType] returning '1' as column: MAX9_26_0_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.loader.Loader] Initializing object from ResultSet: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung#10]
2006-01-24 22:48:38,453 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung#10]
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.StringType] returning 'WPF-J2EE WS03/04' as column: bezeichn2_12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.StringType] returning 'Evaluierung der Vorlesung Java 2 Enterprise Edition (WS 02/03)' as column: beschrei3_12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.StringType] returning '' as column: BEGR4_12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.CharacterType] returning '1' as column: BEGR5_12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.StringType] returning null as column: ABSCH6_12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.BooleanType] returning 'false' as column: ABSCH7_12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.CharacterType] returning '2' as column: TEILN8_12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.CharacterType] returning '2' as column: AUSW9_12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.CharacterType] returning '1' as column: AUSW10_12_1_
2006-01-24 22:48:38,453 DEBUG [org.hibernate.type.StringType] returning '' as column: kennwort12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.TimestampType] returning '2003-09-22 00:00:00' as column: UMFR12_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.TimestampType] returning '2003-10-13 00:00:00' as column: UMFR13_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.CharacterType] returning '1' as column: ERG14_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.TimestampType] returning '2003-09-22 00:00:00' as column: ERG15_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.TimestampType] returning '2003-10-13 00:00:00' as column: ERG16_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.ShortType] returning '1' as column: ERG17_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.CharacterType] returning '1' as column: STUDENTEN18_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.IntegerType] returning '20052' as column: semester12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.IntegerType] returning '-1' as column: stgang12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.IntegerType] returning '-1' as column: fach12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.StringType] returning '-1' as column: gruppe12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.IntegerType] returning '-1' as column: dozent12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.CharacterType] returning '0' as column: fachsem12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.CharacterType] returning '1' as column: MITARBE25_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.IntegerType] returning '100' as column: FACHBER26_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.IntegerType] returning '100' as column: FACHBER27_12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.IntegerType] returning '1' as column: bereich12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.ShortType] returning '17' as column: formula0_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.IntegerType] returning '10' as column: umfrage12_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.BooleanType] returning 'true' as column: freigege2_13_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.BooleanType] returning 'false' as column: ERNEUTE3_13_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.BooleanType] returning 'false' as column: generiert13_1_
2006-01-24 22:48:38,546 DEBUG [org.hibernate.type.ShortType] returning '-1' as column: ANZAHL5_13_1_
2006-01-24 22:48:38,562 DEBUG [org.hibernate.loader.Loader] result set row: 1
....
....
....
2006-01-24 22:48:40,218 DEBUG [org.hibernate.loader.Loader] done processing result set (147 rows)
2006-01-24 22:48:40,218 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-01-24 22:48:40,218 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-01-24 22:48:40,218 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement
2006-01-24 22:48:40,218 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-01-24 22:48:40,218 DEBUG [org.hibernate.jdbc.ConnectionManager] closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.loader.Loader] total objects hydrated: 294



Die Verarbeitung des ResultSet dauert etwa 5 Sekunden. Dann werden Assoziationen aufgelöst und Collection Wrapper erstellt. Im Folgenden sieht man das am Beispiel der Fragen-Collection einer Umfrage, die lazy konfiguriert wurde, oder an den lazy Collections einer Durchfuehrung: auswertungsberechtigte, antwortsaetze, bereitsabgestimmte und tanbloecke:

Code:
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.CollectionLoadContext] creating collection wrapper:[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage.fragen#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.CollectionLoadContext] creating collection wrapper:[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.DfVorlageBasis.auswertungsberechtigte#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.CollectionLoadContext] creating collection wrapper:[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung.antwortsaetze#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.CollectionLoadContext] creating collection wrapper:[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung.bereitsabgestimmte#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.CollectionLoadContext] creating collection wrapper:[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung.tanbloecke#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung#10]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#28]
2006-01-24 22:48:40,218 DEBUG [org.hibernate.engine.CollectionLoadContext] creating collection wrapper:[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage.fragen#28]
....
....
....



Nach diesen Schritten werden die angeblichen non-lazy Collections initialisiert, z. B. die Fragen-Collection einer Umfrage, die lazy konfiguriert ist, wie sich in der Umfrage-Mapping-Datei erkennen lässt:


Code:
2006-01-24 22:48:40,406 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung#186]
2006-01-24 22:48:40,406 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
2006-01-24 22:48:40,406 DEBUG [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage.fragen#10]
2006-01-24 22:48:40,406 DEBUG [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache
2006-01-24 22:48:40,406 DEBUG [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached
2006-01-24 22:48:40,406 DEBUG [org.hibernate.loader.Loader] loading collection: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage.fragen#10]
2006-01-24 22:48:40,406 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-01-24 22:48:40,406 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-01-24 22:48:40,406 DEBUG [org.hibernate.SQL] select fragen0_.FRAGE_UMFRAGE as FRAGE8_1_, fragen0_.id as id1_, fragen0_.id as id15_0_, fragen0_.fragetext as fragetext15_0_, fragen0_.typ as typ15_0_, fragen0_.FRAGEINDEX as FRAGEINDEX15_0_, fragen0_.anmerkfeld as anmerkfeld15_0_, fragen0_.IST_MUSS_FRAGE as IST6_15_0_, fragen0_.seitenzahl as seitenzahl15_0_, fragen0_.FRAGE_UMFRAGE as FRAGE8_15_0_, fragen0_.FRAGE_ZUSGESFRAGE as FRAGE9_15_0_, fragen0_1_.spalten as spalten16_0_, fragen0_1_.zeilen as zeilen16_0_, fragen0_1_.beschriftung as beschrif4_16_0_, fragen0_1_.datentyp as datentyp16_0_, fragen0_1_.ANZAHL_ZEICHEN_MIN as ANZAHL6_16_0_, fragen0_1_.ANZAHL_ZEICHEN_MAX as ANZAHL7_16_0_, fragen0_1_.ANZAHL_ZEICHEN_SUPER_OPT as ANZAHL8_16_0_, fragen0_1_.ANZAHL_ZEICHEN_SUB_OPT as ANZAHL9_16_0_, fragen0_2_.spalten as spalten17_0_, fragen0_2_.DROP_DOWN as DROP3_17_0_, fragen0_3_.spalten as spalten18_0_, fragen0_3_.minanzahl as minanzahl18_0_, fragen0_3_.maxanzahl as maxanzahl18_0_, fragen0_3_.ANZAHL_OPT as ANZAHL5_18_0_, fragen0_5_.KOMPAKTE_DARSTELLUNG as KOMPAKTE2_20_0_, decode(fragen0_.id, fragen0_1_.ID, 1, fragen0_2_.ID, 2, fragen0_3_.ID, 3, fragen0_4_.ID, 4, fragen0_5_.ID, 5, 0) as clazz_0_ from Frage fragen0_, Freiefrage fragen0_1_, Einfachauswahlfrage fragen0_2_, Mehrfachauswahlfrage fragen0_3_, Matrixfrage fragen0_4_, Zusammengesetztefrage fragen0_5_ where fragen0_.id=fragen0_1_.ID(+) and fragen0_.id=fragen0_2_.ID(+) and fragen0_.id=fragen0_3_.ID(+) and fragen0_.id=fragen0_4_.ID(+) and fragen0_.id=fragen0_5_.ID(+) and fragen0_.FRAGE_UMFRAGE=?
2006-01-24 22:48:40,406 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
2006-01-24 22:48:40,406 DEBUG [org.hibernate.type.IntegerType] binding '10' to parameter: 1
2006-01-24 22:48:40,421 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-01-24 22:48:40,421 DEBUG [org.hibernate.loader.Loader] result set contains (possibly empty) collection: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage.fragen#10]
2006-01-24 22:48:40,421 DEBUG [org.hibernate.engine.CollectionLoadContext] uninitialized collection: initializing
2006-01-24 22:48:40,421 DEBUG [org.hibernate.loader.Loader] processing result set
2006-01-24 22:48:40,421 DEBUG [org.hibernate.loader.Loader] result set row: 0
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.IntegerType] returning '110' as column: id15_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Frage#110]
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.IntegerType] returning '2' as column: clazz_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.loader.Loader] Initializing object from ResultSet: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Einfachauswahlfrage#110]
2006-01-24 22:48:40,421 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Einfachauswahlfrage#110]
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.StringType] returning 'Sind "gute" Java-Kenntnisse als Vorbedingung für den Kurs ausreichend?' as column: fragetext15_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.ShortType] returning '2' as column: typ15_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.IntegerType] returning '1' as column: FRAGEINDEX15_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.BooleanType] returning 'false' as column: anmerkfeld15_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.BooleanType] returning 'false' as column: IST6_15_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.ShortType] returning '-1' as column: seitenzahl15_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.IntegerType] returning '10' as column: FRAGE8_15_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.IntegerType] returning null as column: FRAGE9_15_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.ShortType] returning '1' as column: spalten17_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.BooleanType] returning 'false' as column: DROP3_17_0_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.IntegerType] returning '10' as column: FRAGE8_1_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.loader.Loader] found row of collection: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage.fragen#10]
2006-01-24 22:48:40,421 DEBUG [org.hibernate.engine.CollectionLoadContext] reading row
2006-01-24 22:48:40,421 DEBUG [org.hibernate.type.IntegerType] returning '110' as column: id1_
2006-01-24 22:48:40,421 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Frage#110]
2006-01-24 22:48:40,421 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Frage#110]
2006-01-24 22:48:40,421 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] resolved object in session cache: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Frage#110]
2006-01-24 22:48:40,421 DEBUG [org.hibernate.loader.Loader] result set row: 1
...
...
...



Danach werden die Assoziationen der einzelnen Fragen aufgelöst:

Code:
2006-01-24 22:48:40,484 DEBUG [org.hibernate.loader.Loader] done processing result set (17 rows)
2006-01-24 22:48:40,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-01-24 22:48:40,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-01-24 22:48:40,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement
2006-01-24 22:48:40,484 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-01-24 22:48:40,484 DEBUG [org.hibernate.jdbc.ConnectionManager] closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-01-24 22:48:40,484 DEBUG [org.hibernate.loader.Loader] total objects hydrated: 17
2006-01-24 22:48:40,484 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Einfachauswahlfrage#110]
2006-01-24 22:48:40,484 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Umfrage#10]
2006-01-24 22:48:40,484 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] entity found in session cache
2006-01-24 22:48:40,484 DEBUG [org.hibernate.engine.CollectionLoadContext] creating collection wrapper:[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Frage.antworten#110]
2006-01-24 22:48:40,484 DEBUG [org.hibernate.engine.CollectionLoadContext] creating collection wrapper:[de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Einfachauswahlfrage.auswMglMitTexteingabe#110]
2006-01-24 22:48:40,484 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Einfachauswahlfrage#110]
2006-01-24 22:48:40,484 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Einfachauswahlfrage#154]
.....
...
...


Dann werden wieder non-lazy Collections initialisiert:

Code:
2006-01-24 22:48:40,484 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
2006-01-24 22:48:40,484 DEBUG [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Einfachauswahlfrage.auswMglMitTexteingabe#169]
2006-01-24 22:48:40,484 DEBUG [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache
2006-01-24 22:48:40,484 DEBUG [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached
2006-01-24 22:48:40,484 DEBUG [org.hibernate.loader.Loader] loading collection: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Einfachauswahlfrage.auswMglMitTexteingabe#169]
2006-01-24 22:48:40,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-01-24 22:48:40,484 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-01-24 22:48:40,500 DEBUG [org.hibernate.SQL] select auswmglmit0_.EINFACHAUSWFR_MGL as EINFACH10_1_, auswmglmit0_.ID as ID1_, auswmglmit0_.ID as id8_0_, auswmglmit0_1_.AUSWAHLINDEX as AUSWAHLI2_8_0_, auswmglmit0_1_.text as text8_0_, auswmglmit0_1_.MATRIXFR_MGL as MATRIXFR4_8_0_, auswmglmit0_.TEXTEINGABE_MOEGLICH as TEXTEING2_9_0_, auswmglmit0_.TEXTEINGABE_SPALTEN as TEXTEING3_9_0_, auswmglmit0_.TEXTEINGABE_ZEILEN as TEXTEING4_9_0_, auswmglmit0_.datentyp as datentyp9_0_, auswmglmit0_.ANZAHL_ZEICHEN_MIN as ANZAHL6_9_0_, auswmglmit0_.ANZAHL_ZEICHEN_MAX as ANZAHL7_9_0_, auswmglmit0_.ANZAHL_ZEICHEN_SUPER_OPT as ANZAHL8_9_0_, auswmglmit0_.ANZAHL_ZEICHEN_SUB_OPT as ANZAHL9_9_0_, auswmglmit0_.EINFACHAUSWFR_MGL as EINFACH10_9_0_, auswmglmit0_.MEHRFACHAUSWFR_MGL as MEHRFAC11_9_0_ from AUSW_MGL_MIT_TEXTEINGABE auswmglmit0_, Auswahlmoeglichkeit auswmglmit0_1_ where auswmglmit0_.ID=auswmglmit0_1_.id and auswmglmit0_.EINFACHAUSWFR_MGL=?
2006-01-24 22:48:40,500 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
2006-01-24 22:48:40,500 DEBUG [org.hibernate.type.IntegerType] binding '169' to parameter: 1
2006-01-24 22:48:40,562 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-01-24 22:48:40,562 DEBUG [org.hibernate.loader.Loader] result set contains (possibly empty) collection: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Einfachauswahlfrage.auswMglMitTexteingabe#169]
2006-01-24 22:48:40,562 DEBUG [org.hibernate.engine.CollectionLoadContext] uninitialized collection: initializing
2006-01-24 22:48:40,562 DEBUG [org.hibernate.loader.Loader] processing result set
2006-01-24 22:48:40,578 DEBUG [org.hibernate.loader.Loader] result set row: 0
....
...
...
2006-01-24 22:57:21,578 DEBUG [org.hibernate.loader.Loader] loading collection: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung.tanbloecke#186]
2006-01-24 22:57:21,578 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-01-24 22:57:21,578 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-01-24 22:57:21,578 DEBUG [org.hibernate.SQL] select tanbloecke0_.DURCHFUEHRUNG as DURCHFUE4_1_, tanbloecke0_.id as id1_, tanbloecke0_.id as id23_0_, tanbloecke0_.erstelldatum as erstelld2_23_0_, tanbloecke0_.TAN_ANZAHL as TAN3_23_0_, tanbloecke0_.DURCHFUEHRUNG as DURCHFUE4_23_0_ from Tanblock tanbloecke0_ where tanbloecke0_.DURCHFUEHRUNG=?
2006-01-24 22:57:21,578 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
2006-01-24 22:57:21,578 DEBUG [org.hibernate.type.IntegerType] binding '186' to parameter: 1
2006-01-24 22:57:21,578 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-01-24 22:57:21,578 DEBUG [org.hibernate.loader.Loader] result set contains (possibly empty) collection: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung.tanbloecke#186]
2006-01-24 22:57:21,578 DEBUG [org.hibernate.engine.CollectionLoadContext] uninitialized collection: initializing
2006-01-24 22:57:21,578 DEBUG [org.hibernate.loader.Loader] processing result set
2006-01-24 22:57:21,578 DEBUG [org.hibernate.loader.Loader] done processing result set (0 rows)
2006-01-24 22:57:21,578 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-01-24 22:57:21,578 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-01-24 22:57:21,578 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement
2006-01-24 22:57:21,578 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-01-24 22:57:21,578 DEBUG [org.hibernate.jdbc.ConnectionManager] closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-01-24 22:57:21,578 DEBUG [org.hibernate.loader.Loader] total objects hydrated: 0
2006-01-24 22:57:21,578 DEBUG [org.hibernate.engine.CollectionLoadContext] 1 collections were found in result set for role: de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung.tanbloecke
2006-01-24 22:57:21,578 DEBUG [org.hibernate.engine.CollectionLoadContext] collection fully initialized: [de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung.tanbloecke#186]
2006-01-24 22:57:21,578 DEBUG [org.hibernate.engine.CollectionLoadContext] 1 collections initialized for role: de.fhzw.portal.umfragesystem.model.domainmodel.umfrage.Durchfuehrung.tanbloecke
2006-01-24 22:57:21,578 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
2006-01-24 22:57:21,578 DEBUG [org.hibernate.loader.Loader] done loading collection
2006-01-24 22:57:21,578 DEBUG [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized
2006-01-24 22:57:42,015 DEBUG [org.hibernate.transaction.CacheSynchronization] transaction after completion callback, status: 4
2006-01-24 22:57:42,015 DEBUG [org.hibernate.jdbc.JDBCContext] after transaction completion
2006-01-24 22:57:42,015 DEBUG [org.hibernate.impl.SessionImpl] after transaction completion
2006-01-24 22:57:42,031 DEBUG [org.hibernate.transaction.CacheSynchronization] automatically closing session
2006-01-24 22:57:42,031 DEBUG [org.hibernate.impl.SessionImpl] automatically closing session
2006-01-24 22:57:42,031 DEBUG [org.hibernate.impl.SessionImpl] closing session
2006-01-24 22:57:42,031 DEBUG [org.hibernate.jdbc.ConnectionManager] connection already null in cleanup : no action


Bis zum Ende der Verarbeitung sind nun also gut 9 Minuten vergangen. Bei der Betrachtung der Log-Datei ist mir nun folgendes ein- bzw. aufgefallen, was vielleicht die Ursache sein könnte:

Ich bin davon ausgegangen, dass sich das mit dem lazy Attribut hierarchisch verhält - wenn das Set der Fragen lazy konfiguriert ist, werden auch nicht die Sets geladen, die zu einer Frage gehören, obwohl diese nicht lazy sind. Dies ist aber wahrscheinlich nicht der Fall...

Die Fragen einer Umfrage sind lazy:

<set name="fragen" lazy="true" inverse="true" cascade="all-delete-orphan">
<key column="FRAGE_UMFRAGE" />
<one-to-many class="Frage" />
</set>

Ein Frage enthält aber Sets, die nicht lazy sind:

<set name="auswahlMoeglichkeiten" lazy="false" inverse="true"
cascade="all-delete-orphan">
<key column="MATRIXFR_MGL" />
<one-to-many class="Auswahlmoeglichkeit" />
</set>

Eine zusammengesetzte Frage enthält z. B. sogar wieder ein non-lazy Set von Fragen....

Verhält sich also das lazy Attribut nicht so wie ich angenommen habe, sondern werden auch non-lazy Collections initialisiert, die zu Elementen einer lazy Collections gehören?


Grüße,
Matthias


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 3 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.